View Full Version : [Zgemma H9S] Deep standby time? Startup EPG problem
Zgemma H9S running VIX 6.1.004
This is my bedroom box without a hard disk but with a USB stick to store the EPG. It has a direct connection to the quad LNB via a down-lead cable.
I have a couple of timers
1) at 6.15am the box is set to record* from the Sky IEPG channel for 15 minutes to get the EPG.
2) at 6:45am the box is set to record* BBC1 for 15 minutes. This is to ensure that when I switch the box on it goes to last channel the box was switched to and not just a blank screen from the IEPG channel.
The box is set for only SKY FTA channels and only gets the 7 day EPG from the IEPG channel (Freesat EPG is disabled)
*The recording is to trash so I’m not actually filling up the USB stick. This method has worked previously for around a year on this box and my other box, an Extrend 10K. The Extrend doesn’t have the problem detailed below.
The Zgemma H9S is placed in deep standby when not in use
When switched on from, say, 4 hours in deep standby it boots normally. When going to the grid EPG screen the EPG for the current time is missing and for ALL channels. The EPG for programs in the next 30 minutes to 2 hours for all channels is also missing. The period for the missing EPG seems random and different on a different switch on from hours after being in deep standby. The EPG for approx 7 days afterwards is OK. The time displayed in the EPG obtained from the transponder is correct.
Repeatedly going back into the grid EPG screen doesn’t make a difference.
However going to menu → setup - > epg → load, save, and delete EPG cache and selecting load EPG Cache does restore the EPG for the current time and for the missing 30 to 240 minutes. This indicates that the data is available but the box time is possibly hours out during boot up from deep standby?
I repeat, that I’m not seeing this problem on my Extrend ET10K and as the Extrend this is my main box I would notice this immediately. The Zgemma H9S is only used very occasionally and possibly I wouldn’t have noticed the problem in previous versions of OpenVix so I don’t know when the problem started happening.
Could it be the the Zgemma H9S is losing the correct time during deep standby and is using this incorrect time when loading the EPG cache during boot-up, and before fetching the time from the transponder?
The time zone is correctly set.
Maybe a debug log after switching on from deepstandby will give some clues.
NB Set local time (menu/setup/system/logs/Logs settings) in Debug log time format when switching on debug logs
Could this be related?
https://www.world-of-satellite.com/showthread.php?65201-zgemma-h9-twin-and-problem-with-desynced-clock&highlight=local+time
*The recording is to trash so I’m not actually filling up the USB stick. This method has worked previously for around a year on this box and my other box, an Extrend 10K. The Extrend doesn’t have the problem detailed below.Wouldn't a zap timer work? So you end up on th requested channel, but don't do any recording at all?
Could it be the the Zgemma H9S is losing the correct time during deep standby and is using this incorrect time when loading the EPG cache during boot-up, and before fetching the time from the transponder? Whereas that sound plausible from the symptoms it sounds as though the clock is an hour or so in the future at the time the EPG is loaded. Difficult to see how that might occur.
You can get the time from either NTP or the transponder. Try switching to the other one?
Whereas that sound plausible from the symptoms it sounds as though the clock is an hour or so in the future at the time the EPG is loaded. Difficult to see how that might occur.
You can get the time from either NTP or the transponder. Try switching to the other one?
I've already tried both NTP and transponder - same problem with both. Maybe a log file late today or tomorrow.
Wild speculation. Could the box be ignoring the timezone setting in deep standby, or assigning a different default zone?
Wouldn't a zap timer work? So you end up on th requested channel, but don't do any recording at all?
Maybe a zap timer would work but I don't think that is the problem as the same arrangement is working on my Extrend ET10K and has been for some considerable time. Until I recently noticed the problem on the Zgemma this arrangement has been working OK on that box.
Does the zgemma have a real-time clock (RTC)? None of my boxes have RTC. What happens during deep standby is that a simple countdown timer in the panel is initialised with a value at shutdown (the number of seconds to the next wake time) and it counts down to zero and wakes the box at that time. So, timezone etc. would have no effect. It's possible that the timer could be running fast or slow, but that's fairly unusual. My Miraclebox did have an issue with a fast timer after a Front Panel firmware update screwed it up. But, it was quite consistent and would run 20 minutes fast in 24 hours. But that's an unusual case.
The box gets its initial time at boot from the "fake hwclock" which is stored when the box is put into deep standby. Then the clock is updated by NTP or from a transponder. I usually use NTP, but I also have a default channel set to tune at boot time (BBC1 would have a reliable transponder time setting). Obviously, if your particular box has a RTC, then the time should be correct at boot time, providing there hasn't been a power cut. Otherwise, you are dependent on a reliable time being set from a transponder or NTP at boot time. I had a situation yesterday where ntpdate ran twice at startup and advanced the clock briefly to today's date, but I'm running a script to force an NTP sync because of dodgy wifi in the house. Set the debug log running as @birdman suggested and maybe we can spot the issue. If you look in /var/log/messages you may spot the ntpdate settings being actioned.
Update
I switched the box on from deep standby at approx 20:40 and as the picture came up I think the time in the on-screen banner showed 02:xx. I cannot be totally sure as I only caught the display out of the corner of my eye. However in the grid EPG most of the EPG was missing until approx 2am tomorrow morning. For the rest of the x days it was OK. The time shown when selecting the grid EPG was correct. It is configured for transponder time.
63819
Had you put the box in deep standby at 02:00 this morning? That would explain why it briefly showed the stored time.
However, the boot process used NTP to set the clock. This happens at boot, even though you have set the box to use transponder time. What channel was it tuned to? The transponder clock set the time backwards by 37 seconds (see below). The transponder clock usually is accurate to about 2 or 3 seconds on 28.2E, so it's rather strange that it was 37 seconds slow.
20:46:08.7696 [eDVBLocalTimerHandler] dont have correction.. set Transponder Diff
20:46:08.7701 [eDVBLocalTimerHandler] update RTC
20:46:08.7703 [eDVBLocalTimerHandler] time update to 20:45:31
20:46:08.7706 [eDVBLocalTimerHandler] m_time_difference is -37
20:45:31.7708 [eDVBLocalTimerHandler] stepped Linux Time to 20:45:31
20:45:31.7716 [eDVBChannel] getDemux cap=00
20:45:35.9646 [eInputDeviceInit] 1 8b (139) 1
20:45:35.9646 [eRCDeviceInputDev] emit: 1
20:45:35.9663 [InfoBarGenerics] Key: 139 (Make) KeyID='KEY_MENU' Binding='('MENU',)'.
Had you put the box in deep standby at 02:00 this morning? That would explain why it briefly showed the stored time.
However, the boot process used NTP to set the clock. This happens at boot, even though you have set the box to use transponder time. What channel was it tuned to? The transponder clock set the time backwards by 37 seconds (see below). The transponder clock usually is accurate to about 2 or 3 seconds on 28.2E, so it's rather strange that it was 37 seconds slow.
20:46:08.7696 [eDVBLocalTimerHandler] dont have correction.. set Transponder Diff
20:46:08.7701 [eDVBLocalTimerHandler] update RTC
20:46:08.7703 [eDVBLocalTimerHandler] time update to 20:45:31
20:46:08.7706 [eDVBLocalTimerHandler] m_time_difference is -37
20:45:31.7708 [eDVBLocalTimerHandler] stepped Linux Time to 20:45:31
20:45:31.7716 [eDVBChannel] getDemux cap=00
20:45:35.9646 [eInputDeviceInit] 1 8b (139) 1
20:45:35.9646 [eRCDeviceInputDev] emit: 1
20:45:35.9663 [InfoBarGenerics] Key: 139 (Make) KeyID='KEY_MENU' Binding='('MENU',)'.
If it uses NTP then the box would also have to establish a wi-fi connection to the router during boot-up.
I'm attempting to be a bit more systematic with future reporting.
If it uses NTP then the box would also have to establish a wi-fi connection to the router during boot-up.Which is what it should be doing (if you use Wifi).
Mind you, whether the boot sequence waits for it to connect is another matter.
The /var/log/messages file will show when ntpdate runs.
My systems are on Ethernet, so the time is set before enigma2 starts.
update 2
Before the box put into deep standby the EPG was fetched from IEPG
Box put into deep standby at 23:45 Thursday
Box switched on 1:30(ish) Friday
When the BBC HD picture appeared the time in the on-screen banner was 3:13!!
Approx 30 minutes of EPG missing.
It looks like box is unable to maintain time or is corrupted during boot from deep standby.
63820
Time in debug file starts at 01:37, with no massive adjustments.
Not sure about this though (just searching for string "cache").....
Line 26: 01:37:46.3198 [Font] Intializing font cache, using max. 4MB...
Line 101: 01:37:46.3785 [eEPGCache] Initialized EPGCache (wait for setCacheFile call now)
Line 101: 01:37:46.3785 [eEPGCache] Initialized EPGCache (wait for setCacheFile call now)
Line 101: 01:37:46.3785 [eEPGCache] Initialized EPGCache (wait for setCacheFile call now)
Line 173: 01:37:47.9196 [eEPGCache] time updated.. but cache file not set yet.. dont start epg!!
Line 173: 01:37:47.9196 [eEPGCache] time updated.. but cache file not set yet.. dont start epg!!
Line 234: 01:37:50.3649 [eEPGCache] setCacheFile read/write epg data from/to '/etc/enigma2/epg.dat'
Line 234: 01:37:50.3649 [eEPGCache] setCacheFile read/write epg data from/to '/etc/enigma2/epg.dat'
Line 374: 01:38:39.6633 [eEPGCache] time updated.. start EPG Mainloop
Line 384: 01:38:40.5168 [eEPGCache] 129203 events read from /etc/enigma2/epg.dat
Line 539: 01:38:41.1472 [decoder][eDVBText] initCache
Line 667: 01:41:39.0847 [eEPGCache] event 67fa not found in epgcache
Line 667: 01:41:39.0847 [eEPGCache] event 67fa not found in epgcache
update 2
Before the box put into deep standby the EPG was fetched from IEPG
Box put into deep standby at 23:45 Thursday
Box switched on 1:30(ish) Friday
When the BBC HD picture appeared the time in the on-screen banner was 3:13!!
Approx 30 minutes of EPG missing.
It looks like box is unable to maintain time or is corrupted during boot from deep standby.
63820
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. I've seen this happen on my box, but it's a very rare occurrence. You can tell if this is happening by looking at /var/log/messages (see post #7 and #11). You will see where ntpdate steps the time. A copy of this file (as well as the debug log) would be useful to see it it happens again.
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. I've seen this happen on my box, but it's a very rare occurrence. You can tell if this is happening by looking at /var/log/messages (see post #7 and #11). You will see where ntpdate steps the time. A copy of this file (as well as the debug log) would be useful to see it it happens again.
You could be correct but its not a rare event on my box. It seems to happen every time that the box is in deep standby for a few hours. Note:my box is connected via wi-fi to the router. In normal operation I only use the network connection for Vix upgrades and in this instance FTP transfers. It is in general a viewing only box with no recording or timeshift.
At approx 13:38 the box was placed into deep standby with a full EPG populated
At approx 16:42 the box was switched on. The time displayed in the banner when the picture appeared was first 16:42 then 19:47 and then again 16:42. Approx 2.25 hours of the EPG was missing.
Time between turn off and turn on = 3 hours 4 minutes. The time display of 19:47 is twice that period from last switch off.
I have my EPG configured to show 30 minutes of past history (menu/setup/EPG/EPG setting/Maintain old EPGdata for =30) and so the missing EPG is roughly the 3 hours additional time to 19:47
63824
63825
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.
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.
I use transponder time as well, but still see this cron job running by default......
63828
I use transponder time as well, but still see this cron job running by default......
63828
My router is configured as a time server in the home network and is using 2.europe.pool.ntp.org as the time server.
Sorry about the delayed response, but was away in the real world for several hours :beer_toast:
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.
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!
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?
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?
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 15Sorry, 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.
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.
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).
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.
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
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?
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
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.
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).
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?
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
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.
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.
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).
...
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.
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
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.
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.
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.
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.
May 10 12:15:34 ax61 daemon.notice ntpdate[2255]: adjust time server 188.125.64.6 offset -0.001396 sec
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)
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.
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.
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?
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
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
I believe that the first one is the initial time setting [PID 1602], which comes from the network if-up.d call of ntpdate-sync. This has the "-b" parameter which forces a time step (although the man pages for ntpdate indicate the it will do a time step by default if the time difference is more than 0.5 seconds, otherwise it does a slew).
The second one [1714] comes from the default ntpdate-sync command which is issued by something in enigma. I asked a question about this in #58 above.
I think the third one [1729] may be happening because you have "sync by NTP" set, maybe? I don't see a third one in my startup, which is using "sync by transponder".
I have established why ntpdate-sync is taking so long to run. By default, the ntpdate command checks up to eight time servers to establish a reasonable guess at an accurate time. As an experiment I reduced that check to one time server. See below, where it took 2 seconds instead of the usual 8-9 seconds to run. You will note the ntpdate command stepped the time by default as it was just over a second out. The transponder time is slightly off.
May 10 16:30:01 ax61 authpriv.info crond[2343]: pam_unix(crond:session): session opened for user root(uid=0) by (uid=0)
May 10 16:30:01 ax61 cron.info CROND[2344]: (root) CMD (/usr/bin/ntpdate-sync silent)
May 10 16:30:01 ax61 user.notice root: ntpdate-sync running
May 10 16:30:01 ax61 user.notice root: ntpdate-sync checking ntpdate
May 10 16:30:03 ax61 cron.info CROND[2343]: (root) CMDOUT (10 May 16:30:03 ntpdate[2349]: step time server 188.125.64.7 offset +1.016450 sec)
May 10 16:30:03 ax61 cron.info CROND[2343]: (root) CMDEND (/usr/bin/ntpdate-sync silent)
May 10 16:30:03 ax61 authpriv.info CROND[2343]: pam_unix(crond:session): session closed for user root
I'm at the end of my limited expertise at this point. Foregrounding ntpdate-sync seems to be working to give me an accurate date/time and the debug log has the correct time in the filename.
I believe that the first one is the initial time setting [PID 1602], which comes from the network if-up.d call of ntpdate-sync. This has the "-b" parameter which forces a time step (although the man pages for ntpdate indicate the it will do a time step by default if the time difference is more than 0.5 seconds, otherwise it does a slew).
The second one [1714] comes from the default ntpdate-sync command which is issued by something in enigma. I asked a question about this in #58 above.
I think the third one [1729] may be happening because you have "sync by NTP" set, maybe? I don't see a third one in my startup, which is using "sync by transponder".
I also had my time configured for NTP when I had 3 start up calls to to NTP but on the next test putting the box into deep standby for and hour then removing the power for an hour I only had 2 NTP calls on the next boot (resulting in the clock being two hours in the future). There seem some inconsistency between switch on from removed power.
I have established why ntpdate-sync is taking so long to run. By default, the ntpdate command checks up to eight time servers to establish a reasonable guess at an accurate time. As an experiment I reduced that check to one time server. See below, where it took 2 seconds instead of the usual 8-9 seconds to run. You will note the ntpdate command stepped the time by default as it was just over a second out. The transponder time is slightly off.
If the NTP is taking 2 to 8 seconds to obtain a new value why do the offsets in the time shown in the message file only differ by 300 to 400 microseconds between the two NTP calls?
If the NTP is taking 2 to 8 seconds to obtain a new value why do the offsets in the time shown in the message file only differ by 300 to 400 microseconds between the two NTP calls?
Because there are two instances running (or finishing) at approximately the same time. ntpdateuses whatever value the system clock has at that instant, calculates an offset and steps the time to that value. Both instances have the same (old) clock value and calculate the same offset. The first instance to finish, steps the clock forward by that value. The clock now has the correct time. The second instance steps the clock forward by the same offset and the clock is now in the future. The problem here is that the clock is not being set to an actual time value - it's being stepped by a number of calculated seconds/microseconds.
I found that tweaking /usr/bin/ntpdate-sync to foreground the calls (by commenting out the "(" in line 55 and the ") &" in line 79 using a "#" is working great for me. I'm sure the devs will find a better way!
So why allow multiple instances?
e.g. try this: https://gist.github.com/beugley/43f3feb8c532f7cc07cbcb3ea3ccd203
Or something like this to start the script:
ps -C script.name.sh > /dev/null 2>&1 || ./script.name.sh
Thanks @Huevos, but beyond my limited skill level. @birdman may have to investigate a bit deeper as to why multiple instances are fired.
If ntpdate must set the clock by this adding/subtracting an offset method (rather than just asking the time and setting the clock to the answer obtained) then there should really be a semaphore making sure only one instance at a time is allowed to be in the middle of manipulating the clock.
At the moment I'm experimenting by commenting out the backgrounding in ntpdate-sync.I take it you mean the one from the if-up.d scripts?
I just can't see the initial time stepping logged anywhere now.syslog isn't running when the network comes up.
Question for @birdman. Does the following code in ntpdate-sync check that it is being called by if-up.d?Yes.
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?No.
As the comments says, the idea is that at boot time (and early in the boot time) you want the clock to be correct. So you slew it.
Later on you expect the time to be nearly right, so just make minor adjustments to the clock rate with the intentions of these heading towards zero.
This is from the ntpdate man page on Ubuntu (not necessarily exactly the same as the busybox version on Vix).
Time adjustments are made by ntpdate in one of two ways. If ntpdate determines the clock is in error more than 0.5 second it will simply step the time by calling the system settimeofday() routine. If the error is less than 0.5 seconds, it will slew the time by calling the system adjtime() routine. The latter technique is less disruptive and more accurate when the error is small, and works quite well when ntpdate is run by cron every hour or two.
So why allow multiple instances?I've asked that at least twice already.
e.g. try this: https://gist.github.com/beugley/43f3feb8c532f7cc07cbcb3ea3ccd203Not a reliable way to do it (it's not atomic).
Taking a file-system lock is far better.
EDIT: I meant "using the file-system to take the lock". It doesn't actually need to use filesystem locks.
I take it you mean the one from the if-up.d scripts?
I can only find one instance of the ntpdate-sync script. It's in /usr/bin/. Do you think there's another? Removing the backgrounding solves the issue for me completely. Those extra seconds of delay seem to prevent the collision between the two calls.
Do you know what is calling ntpdate-sync when it is logged in the debug log early after the start of enigma:
< 19.9117> 15:58:46.0095 [Console] command: /usr/bin/ntpdate-sync
< 19.9118> 15:58:46.0096 [eConsoleAppContainer] Starting /bin/sh
< 19.9123> 15:58:46.0100 [Console] pid = 2254
EDIT - in reference to the stepping and slewing - stepping happens first time (if called from if-up.d) and forced by the "-b" parameter. Slewing happens on subsequent runs, providing the time adjustment is less than 0.5 seconds, otherwise ntpdate steps the time. I've read the man pages and played with the various parameter settings.
I can only find one instance of the ntpdate-sync script. It's in /usr/bin/. Do you think there's another?No.
But it occurs to me that adding code to ensure it's only running once at a time can be done quite simply within the ntpdate-sync script itself using standard commands.
I'll have a go this evening....
Thanks @birdman. Do you know what's calling ntpdate-sync from enigma as I asked in post #76?
Thanks @birdman. Do you know what's calling ntpdate-sync from enigma as I asked in post #76?Yes, I know what is calling ntp-sync. I fixed that already. Needs testing. But I think I will remove the cronjob.
No.
But it occurs to me that adding code to ensure it's only running once at a time can be done quite simply within the ntpdate-sync script itself using standard commands.
I'll have a go this evening....
Don't bother with that.
Yes, I know what is calling ntp-sync. I fixed that already. Needs testing. But I think I will remove the cronjob.
Can you enlighten?
EDIT - ignore. Found it in StartEnigma.py
Can test if you wish.
Can you enlighten?
EDIT - ignore. Found it in StartEnigma.py
Can test if you wish.So ignoring the cronjob for the time being... try these.
/usr/lib/enigma2/python/StartEnigma.py
/usr/lib/enigma2/python/Screens/Time.py
/usr/lib/enigma2/python/Components/NetworkTime.py
Thanks @Huevos. Will be about an hour or so before I can test.
EDIT - all seems ok so far. I presume Time.py is used on initial start (First Install Wizard)? So, should I force a run through that?
As regards the console command to run ntpdate-sync in StartEnigma.py - you removed that, so it's not appearing in the messages log. However, the if-up.d (or whatever) seems to have generated a couple of calls to ntpdate. See time 17:31:23/24. (17:29 is the fake time). Interestingly, the cron job kicked in also as it was just past the scheduled time for that. But all times were "adjusted" (slewed) not "stepped" other than the initial one.
May 11 17:29:22 ax61 cron.info crond[2113]: (CRON) INFO (Syslog will be used instead of sendmail.)
May 11 17:29:22 ax61 cron.info crond[2113]: (CRON) INFO (RANDOM_DELAY will be scaled with factor 17% if used.)
May 11 17:29:22 ax61 kern.info kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
May 11 17:29:23 ax61 daemon.info avahi-daemon[2103]: Server startup complete. Host name is ax61.local. Local service cookie is 936921535.
May 11 17:29:23 ax61 daemon.info avahi-daemon[2103]: Service "FTP file server on ax61" (/services/ftp.service) successfully established.
May 11 17:29:24 ax61 daemon.info avahi-daemon[2103]: Joining mDNS multicast group on interface wlan0.IPv6 with address fe80::2e0:4cff:fe0d:398e.
May 11 17:29:24 ax61 daemon.info avahi-daemon[2103]: New relevant interface wlan0.IPv6 for mDNS.
May 11 17:29:24 ax61 daemon.info avahi-daemon[2103]: Registering new address record for fe80::2e0:4cff:fe0d:398e on wlan0.*.
May 11 17:31:23 ax61 daemon.notice ntpdate[2046]: step time server 194.58.202.148 offset +113.065724 sec
May 11 17:31:24 ax61 daemon.err ntpdate[2119]: no server suitable for synchronization found
May 11 17:31:24 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p1): udf_fill_super: No partition found (2)
May 11 17:31:24 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p1): udf_fill_super: No partition found (2)
May 11 17:31:24 ax61 kern.info kernel: yaffs: dev is 187695105 name is "mmcblk0p1" rw
May 11 17:31:24 ax61 kern.info kernel: yaffs: passed flags ""
May 11 17:31:24 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.1,"mmcblk0p1"
May 11 17:31:24 ax61 kern.debug kernel: yaffs: yaffs: MTD device 1 either not valid or unavailable
May 11 17:31:25 ax61 kern.info kernel: yaffs: dev is 187695105 name is "mmcblk0p1" rw
May 11 17:31:25 ax61 kern.info kernel: yaffs: passed flags ""
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.1,"mmcblk0p1"
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: MTD device 1 either not valid or unavailable
May 11 17:31:25 ax61 kern.info kernel: tntfs info (device mmcblk0p1, pid 2151): ntfs_fill_super(): fail_safe is enabled.
May 11 17:31:25 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p3): udf_fill_super: No partition found (2)
May 11 17:31:25 ax61 kern.warn kernel: UDF-fs: warning (device mmcblk0p3): udf_fill_super: No partition found (2)
May 11 17:31:25 ax61 kern.info kernel: yaffs: dev is 187695107 name is "mmcblk0p3" rw
May 11 17:31:25 ax61 kern.info kernel: yaffs: passed flags ""
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.3,"mmcblk0p3"
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May 11 17:31:25 ax61 kern.info kernel: yaffs: dev is 187695107 name is "mmcblk0p3" rw
May 11 17:31:25 ax61 kern.info kernel: yaffs: passed flags ""
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: Attempting MTD mount of 179.3,"mmcblk0p3"
May 11 17:31:25 ax61 kern.debug kernel: yaffs: yaffs: MTD device 3 either not valid or unavailable
May 11 17:31:25 ax61 kern.info kernel: tntfs info (device mmcblk0p3, pid 2190): ntfs_fill_super(): fail_safe is enabled.
May 11 17:31:33 ax61 daemon.info automount[2071]: key "logs" not found in map source(s).
May 11 17:31:54 ax61 authpriv.info crond[2256]: pam_unix(crond:session): session opened for user root(uid=0) by (uid=0)
May 11 17:31:54 ax61 cron.info CROND[2257]: (root) CMD (/usr/bin/ntpdate-sync silent)
May 11 17:32:01 ax61 daemon.notice ntpdate[2261]: adjust time server 85.91.1.164 offset +0.007328 sec
May 11 17:32:01 ax61 cron.info CROND[2256]: (root) CMDEND (/usr/bin/ntpdate-sync silent)
May 11 17:32:01 ax61 authpriv.info CROND[2256]: pam_unix(crond:session): session closed for user root
Don't bother with that.Done it already.
This is a better ntpdate-sync script. Just exits if another is already running.
EDIT: replaced with a better(?) version in https://www.world-of-satellite.com/showthread.php?65253-Multiple-NTP-Update&p=525318&viewfull=1#post525318
Done it already.
This is a better ntpdate-sync script. Just exits if another is already running.
63872
I'll leave that for a while until my previous debug/messages files are looked at.
But, I notice that you removed the backgrounding from line 52 in the original file and moved it to the actual ntpdate call. The original also has a commented out line 63 (an ampersand). So, in your new script all the lockfile creation and check is in the foreground, correct? Maybe the original script was somewhat buggy to begin with:whistle:
Lock file = not a good idea.
So, in your new script all the lockfile creation and check is in the foreground, correct?Yes. the comments imply that the backgrounding is done because of how ntpdate/ntpd run in systemd systems.
The locking (or whatever you call what is now there) has got nothing to do with this, so there's no reason to background it.
Yes. the comments imply that the backgrounding is done because of how ntpdate/ntpd run in systemd systems.
The locking (or whatever you call what is now there) has got nothing to do with this, so there's no reason to background it.
But doesn't vix use init, rather than systemd? Just asking.
But doesn't vix use init, rather than systemd? Just asking.Yes. But the script might be used elsewhere. Since I didn't need to break the logic, I didn't.
Powered by vBulletin® Version 4.2.5 Copyright © 2024 vBulletin Solutions Inc. All rights reserved.