The lock file has never been created. And it shouldn't need a lock file either (ntpdate itself should probably be locking, but that is a separate issue).
It's a trivial matter to run the first ntpdate in the foreground so that the system services are started with the correct time if it is available. Then the issue goes away.
MiracleBox Prem Twin HD - 2@DVB-T2 + Xtrend et8000 - 5(incl. 2 different USBs)@DVB-T2[terrestrial - UK Freeview HD, Sandy Heath] - LAN/USB-stick/HDD
ntpdate is a deprecated time setting facility in linux (it's not been changed in years). It's normally only used once at system start-up in linux systems and then ntpd is used to maintain the system clock accurately if needed. Using ntpdate to poll a single server (in my case) is probably not very reliable. ntpd is better because one normally provides a list of time servers with a preferred option so that it can poll several and then work out which is accurate. Once the system time settles down servers are polled less frequently. I'm fairly sure that ntpdate does not use any locking mechanism to prevent it being run multiple times.
However, for E2 systems, ntpdate is probably "good enough" and the fact that it is scheduled to run at 30 minute (or greater) intervals is probably ok. What you're saying about ensuring it is run at an appropriate time (when network interfaces are actually up) is correct and we should ensure that it happens before the various timer checks (or log naming) are done. If ntpdate fails to get a response at boot time, then the system should use the transponder time instead. If it fails on one of the 30 minute checks, then just carry on with the existing time.
In the two days since I've changed /etc/default/fake-hwclock to "force", I have not had any problem with time setting. The system starts at zero, ntpdate seems to start too early and returns nothing which means the clock check decides to use the transponder time in preference at boot. Then ntpdate runs at 30 minute intervals and updates the time. The debug log file is dated 1/1/1970.
So, after having a year of correctly dated log files and no issues with time keeping by NTP on my HD51, I am now in a situation where I can either have the time randomly setting at startup to any time in the future with log files dated as of the previous shutdown time OR I can have the time running reasonably stable with log files dated 1/1/1970 all by either commenting out or enabling the "force" parameter in /etc/default/fake-hwclock.
GB Quad Plus, Mut@nt HD51, AX HD61, 80cm dish and Supreme Dark motor. Sony STR-DN 1060, Sony UHP-H1 Bluray, Odroid N2+ (CoreElec), Monitor Audio Bronze 5.1 speakers
As an aside - is it usual to have a script in /etc/init.d, a parameter file in /etc/default and another script in /bin all with the exact same name - e.g. "fake-hwclock"? It seems confusing to me. Just asking
GB Quad Plus, Mut@nt HD51, AX HD61, 80cm dish and Supreme Dark motor. Sony STR-DN 1060, Sony UHP-H1 Bluray, Odroid N2+ (CoreElec), Monitor Audio Bronze 5.1 speakers
It does, the pre-requisites for it just haven't been installed inside the image previously. I changed that yesterday.
I have also added a 500ms sleep between checks if the network is up.
This should help if the network is slow to come up.
If this alone doesn't solve the problem of ntpdate-sync failing on slow interfaces, we can increase the retry counter too.
The clock check decices nothing, you decide:
If you set E2 to use DVB time, it will sync time using DVB right after start and continue to sync the clock with DVB at run-time, no matter what the time was set to before by fake-hwclock, restoring the FP-RTC or ntpdate.
If you set E2 to use NTP time, it will sync time using NTP right after start and continue to sync the clock with NTP at run-time, no matter what the time was set to before by fake-hwclock, restoring the FP-RTC or ntpdate.
The only problem I can see on your setup is that there is a timing issue: ntpdate-sync from boot (if-up) runs at the very same time as E2s own first NTP sync and thus does a double forward.
As soon as OpenViX builds with latest git changes, this issue will be gone, as ntpdate-sync will no longer allow concurrent runs.
For the second issue (on-boot-ntpdate-sync failing on slow networks), only tests, e.g. by you, can show if 0.5s wait time between 5 retries is enough, if not, we will increase retries.
Receiver/TV:Pay TV: Redlight Mega, Brazzers TV Europe, XXL, HD-, Sky
- Vu+ Duo² 4*S2+2*C / 1.8TB HDD / OpenATV 6.1@Samsung 50" Plasma
- AX Quadbox 2400 / 2*S2/2*C / 930GB HDD / OpenATV 6.1@Samsung 32" LCD
- Vu+ Solo² / 465GB HDD / OpenATV 6.1
- Vu+ Solo² / 230GB HDD / OpenATV 6.1
- DVBSky S2-Twin-Tuner PCIe@Samsung SyncMaster T240HD (PC)
Internet: Unitymedia 1play 100 / Cisco EPC3212 + Linksys WRT1900ACS + Fritz!Box 7390 / IPv4 (UM) + IPv6 (HE)
Receiver/TV:Pay TV: Redlight Mega, Brazzers TV Europe, XXL, HD-, Sky
- Vu+ Duo² 4*S2+2*C / 1.8TB HDD / OpenATV 6.1@Samsung 50" Plasma
- AX Quadbox 2400 / 2*S2/2*C / 930GB HDD / OpenATV 6.1@Samsung 32" LCD
- Vu+ Solo² / 465GB HDD / OpenATV 6.1
- Vu+ Solo² / 230GB HDD / OpenATV 6.1
- DVBSky S2-Twin-Tuner PCIe@Samsung SyncMaster T240HD (PC)
Internet: Unitymedia 1play 100 / Cisco EPC3212 + Linksys WRT1900ACS + Fritz!Box 7390 / IPv4 (UM) + IPv6 (HE)
I was referring to the ntpdate binary - not ntpdate-sync
My box is set to use NTP time, but if there is no time available (for whatever reason) at boot, then E2 seems to use transponder time for the initial clock setting, then it reverts to NTP at the specified intervals (default 30 mins) after that.
I think (I'm pretty sure!) that you are correct. It's the major change which has happened in the past month or so. The old E2 ntpdate synchronisation always worked in my setup. Now it's been commented out and the ntpdate-sync script is failing as it seems to be starting too early as you say. However, I still have the situation where I'm getting a double forward of time. Is E2 still running an ntpdate call somewhere? I thought it had been suppressed?
GB Quad Plus, Mut@nt HD51, AX HD61, 80cm dish and Supreme Dark motor. Sony STR-DN 1060, Sony UHP-H1 Bluray, Odroid N2+ (CoreElec), Monitor Audio Bronze 5.1 speakers
Ok - but it does not seem to me to be best practice to name scripts and settings files exactly the same. I run several Raspberry Pis and I had asked in the past for the devs here on Vix to introduce the fake hwclock mechanism as I hated the 1/1/1970 filenames on the debug logs!
Now I'm not so sure it's such a good ideas but maybe we'll get there in the end!
I'll run a dev build for my HD51 later today and incorporate your changes and re-test, thanks.
GB Quad Plus, Mut@nt HD51, AX HD61, 80cm dish and Supreme Dark motor. Sony STR-DN 1060, Sony UHP-H1 Bluray, Odroid N2+ (CoreElec), Monitor Audio Bronze 5.1 speakers
You have to see the whole package though
That part is only about getting the ntpdate-sync from where it was before (As a workaround in enigma2.sh) to where it belongs to (System boot).
Workarounds are always bad, because in the end they kick you into the ass ... previously, the very same (double time jump) was possible, just on fast networks rather than slow ones ...
As soon as we have a good value for the amount of retries, it will work cleanly for all, networks coming up slowly, "mediumly" and fastly ...
Yes.
If you set it to use NTP, is simply periodically calls ntpdate-sync ...
Receiver/TV:Pay TV: Redlight Mega, Brazzers TV Europe, XXL, HD-, Sky
- Vu+ Duo² 4*S2+2*C / 1.8TB HDD / OpenATV 6.1@Samsung 50" Plasma
- AX Quadbox 2400 / 2*S2/2*C / 930GB HDD / OpenATV 6.1@Samsung 32" LCD
- Vu+ Solo² / 465GB HDD / OpenATV 6.1
- Vu+ Solo² / 230GB HDD / OpenATV 6.1
- DVBSky S2-Twin-Tuner PCIe@Samsung SyncMaster T240HD (PC)
Internet: Unitymedia 1play 100 / Cisco EPC3212 + Linksys WRT1900ACS + Fritz!Box 7390 / IPv4 (UM) + IPv6 (HE)
Joe_90 (20-01-18)
Hi im not sure if this is releated I have EPG xml files downloading on boot and just had an issue with enigma2 taking agies to load. I created a debug log with Talnet, this is the part I noticed
I deleted the prestart sh and enigma2 booted fineCode:Traceback (most recent call last): File "/usr/lib/python2.7/site-packages/twisted/internet/defer.py", line 310, in addCallbacks File "/usr/lib/python2.7/site-packages/twisted/internet/defer.py", line 653, in _runCallbacks File "/usr/lib/python2.7/site-packages/twisted/internet/base.py", line 441, in _continueFiring File "/usr/lib/python2.7/site-packages/twisted/internet/base.py", line 671, in disconnectAll --- <exception caught here> --- File "/usr/lib/python2.7/site-packages/twisted/python/log.py", line 103, in callWithLogger File "/usr/lib/python2.7/site-packages/twisted/python/log.py", line 86, in callWithContext File "/usr/lib/python2.7/site-packages/twisted/python/context.py", line 122, in callWithContext File "/usr/lib/python2.7/site-packages/twisted/python/context.py", line 85, in callWithContext File "/usr/lib/python2.7/site-packages/twisted/internet/unix.py", line 420, in connectionLost exceptions.OSError: [Errno 2] No such file or directory: '/tmp/hotplug.socket'
Is this related to time issues or completely different? If a different issues apologies.
Edit after another resart I still get the same issue. Ill re flash and start a new thread if needed.
Last edited by dsayers; 20-01-18 at 17:21.
MiracleBox Prem Twin HD - 2@DVB-T2 + Xtrend et8000 - 5(incl. 2 different USBs)@DVB-T2[terrestrial - UK Freeview HD, Sandy Heath] - LAN/USB-stick/HDD
So it's not actually detracted as a means of setting the time initially. Although many system would have an RTC and hence just use NTP.
Correct. As far as I can tell fake-hwclock was installed just so that a (almost) valid time could always be set at start-up. But this was only ever needed for services which required network access (e.g. ssl certificates for VPN) and hence in all situations where it was needed a synchronous ntpdate-sync would have been better, and simpler to implement.So, after having a year of correctly dated log files and no issues with time keeping by NTP on my HD51, I am now in a situation where I can either have the time randomly setting at startup to any time in the future with log files dated as of the previous shutdown time OR I can have the time running reasonably stable with log files dated 1/1/1970 all by either commenting out or enabling the "force" parameter in /etc/default/fake-hwclock.
MiracleBox Prem Twin HD - 2@DVB-T2 + Xtrend et8000 - 5(incl. 2 different USBs)@DVB-T2[terrestrial - UK Freeview HD, Sandy Heath] - LAN/USB-stick/HDD
MiracleBox Prem Twin HD - 2@DVB-T2 + Xtrend et8000 - 5(incl. 2 different USBs)@DVB-T2[terrestrial - UK Freeview HD, Sandy Heath] - LAN/USB-stick/HDD
MiracleBox Prem Twin HD - 2@DVB-T2 + Xtrend et8000 - 5(incl. 2 different USBs)@DVB-T2[terrestrial - UK Freeview HD, Sandy Heath] - LAN/USB-stick/HDD
Thanks @birdman. It did confuse me, but I thought it was maybe a "style" thing. I'm an old-school programmer from the time before object-oriented languages. I haven't programmed since the early 80's as my job description changed over time. I realise that the coding was lifted for various distributions unchanged and that it would be a maintenance issue - just thought it was sloppy as I was always taught to use "meaningful data names". Anyway - enough of that!
I cleaned up my build system and pulled from the OE 4.2 branch and built my HD51 image as a clean OpenVix 5.2.000 dev. I flashed it clean (no restores) and set up the box to use NTP from the default "pool.ntp.org" and shut it down at 02:18 this morning (21/01). I booted at about 10:45 this morning.
The log shows ntpdate-sync being kicked off at 23.212 seconds and returning some 81 seconds later and the system time of 10:46:29 being set. Subsequent updates of ntpdate-sync (at 30 minute intervals) return within about 6 seconds.Code:< 23.121> [Volume] setValue 50 < 23.158> [eDVBVolumecontrol] Setvolume: raw: 100 100, -1db: 0 0 < 23.163> [eDVBVolumecontrol] Setvolume: raw: 50 50, -1db: 32 32 < 23.184> [Skin] processing screen Scart: < 23.191> [Skin] processing screen AutoVideoModeLabel: < 23.194> [LogManager] Trim Poll Started < 23.212> [LogManager] Trash Poll Started < 23.212> [NetworkTime] Updating < 23.212> [Console] command: /usr/bin/ntpdate-sync <------------------------------------------- ntpdate-sync kicked off < 23.212> [eConsoleAppContainer] Starting /bin/sh < 23.214> [eDVBFrontend] close frontend 1 < 23.214> [eDVBFrontend] sendTone allowed only in feSatellite (2) < 23.222> [Navigation] playing 1:0:16:451:3E9:2174:EEEE0000:0:0:0: < 23.279> [eDVBServicePlay] timeshift < 23.279> [eDVBServicePlay] timeshift < 23.280> [eDVBServicePlay] timeshift < 23.281> [eDVBServicePlay] timeshift < 23.281> [eDVBServicePlay] timeshift < 23.281> [eDVBServicePlay] timeshift < 23.282> [Notifications] RemovePopup, id = ZapError < 23.297> [eDVBResourceManager] allocate channel.. 03e9:2174 < 23.297> [eDVBFrontend] opening frontend 1 < 23.306> [eDVBFrontend] (1)tune < 23.306> [eDVBFrontend] tune setting type to 2 from 0 < 23.306> [eDVBChannel] OURSTATE: tuning < 23.306> [eDVBServicePMTHandler] allocate Channel: res 0 < 23.306> [eDVBCIInterfaces] addPMTHandler 1:0:16:451:3E9:2174:EEEE0000:0:0:0: < 23.306> [eDVBChannel] getDemux cap=00 < 23.306> [eDVBResourceManager] allocate demux cap=00 < 23.306> [eDVBResourceManager] allocating demux adapter=0, demux=0, source=-1 fesource=1 < 23.306> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.311> [eHdmiCEC] received message 00 8E 00 < 23.312> [Console] finished: ('/sbin/ip', '/sbin/ip', '-o', 'addr', 'show', 'dev', 'eth0') < 23.321> [Console] command: route -n | grep eth0 < 23.321> [eConsoleAppContainer] Starting /bin/sh < 23.324> [Console] finished: ('/sbin/ip', '/sbin/ip', '-o', 'addr', 'show', 'dev', 'wlan0') < 23.325> [Console] command: route -n | grep wlan0 < 23.325> [eConsoleAppContainer] Starting /bin/sh < 23.329> [Task] job Components.Task.Job name=LogManager #tasks=1 completed with [] in None < 23.330> [eDVBFrontend] startTuneTimeout 5000 < 23.331> [eDVBFrontend] setVoltage 0 < 23.332> [eDVBFrontend] setFrontend 1 < 23.332> [eDVBFrontend] setting frontend 1 < 23.333> [eDVBFrontend] (1)fe event: status 0, inversion off, m_tuning 1 < 23.335> [LogManager] probing folders < 23.347> [LogManager] found following log's: ['/home/root/logs'] < 23.347> [LogManager] looking in: /home/root/logs < 23.348> [LogManager] /home/root/logs: bytesToRemove -10463154 < 23.350> [Task] job Components.Task.Job name=LogManager #tasks=1 completed with [] in None < 23.359> [Console] finished: route -n | grep eth0 < 23.367> [Console] finished: route -n | grep wlan0 < 23.367> 0.0.0.0 < 23.367> 192.168 < 23.369> [Network] read configured interface: {'lo': {'dhcp': False}, 'wlan0': {'dhcp': True}, 'eth0': {'dhcp': True}} < 23.370> [Network] self.ifaces after loading: {'wlan0': {'preup': '\tpre-up wpa_supplicant -iwlan0 -c/etc/wpa_supplicant.wlan0.conf -B -dd -Dnl80211 || true\n', 'predown': '\tpre-down wpa_cli -iwlan0 terminate || true\n', 'ip': [192, 168, 0, 126], 'up': True, 'mac': '00:e0:4c:0d:39:8e', 'dhcp': True, 'bcast': [192, 168, 0, 255], 'netmask': [255, 255, 255, 0], 'gateway': [192, 168, 0, 1]}, 'eth0': {'preup': False, 'predown': False, 'ip': [0, 0, 0, 0], 'up': False, 'mac': '00:6c:fd:ff:51:6b', 'dhcp': True, 'netmask': [0, 0, 0, 0], 'gateway': [0, 0, 0, 0]}} < 23.377> SerienRecorder plugin not found < 23.377> EPG Refresh Plugin not found < 23.379> [OpenWebif] no plugins to load < 23.380> [OpenWebif] started on 80 < 23.381> [Avahi] Not running yet, cannot register type _http._tcp. < 23.706> [eDVBFrontend] (1)fe event: status 1f, inversion off, m_tuning 2 < 23.706> [eDVBChannel] OURSTATE: ok < 23.706> [eDVBLocalTimerHandler] channel 0xf60b50 running < 23.706> [eEPGCache] channel 0xf60b50 running < 23.706> [eDVBChannel] getDemux cap=00 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.706> [eDVBResourceManager] stop release channel timer < 23.706> [eDVBChannel] getDemux cap=01 < 23.706> [eDVBResourceManager] allocate demux cap=01 < 23.706> [eEPGCache] next update in 2 sec < 23.706> [eDVBResourceManager] allocating shared demux adapter=0, demux=0, source=1 < 23.706> [eDVBServicePMTHandler] ok ... now we start!! < 23.706> [eDVBServicePlay] eventNewProgramInfo timeshift_enabled=0 timeshift_active=0 < 23.706> [eDVBServicePlay] have 1 video stream(s) (0451), and 1 audio stream(s) (04b5), and the pcr pid is 1ffe, and the text pid is 0519 < 23.706> [eDVBChannel] getDemux cap=01 < 23.713> [eTSMPEGDecoder] decoder state: play, vpid=0451, apid=04b5 < 23.713> [eDVBPCR0] DMX_SET_PES_FILTER pid=0x1ffe ok < 23.713> [eDVBPCR0] DEMUX_START ok < 23.713> [eDVBAudio0] DMX_SET_PES_FILTER pid=0x04b5 ok < 23.713> [eDVBAudio0] DEMUX_START ok < 23.713> [eDVBAudio0] AUDIO_SET_BYPASS bypass=1 ok < 23.713> [eDVBAudio0] AUDIO_PAUSE ok < 23.713> [eDVBAudio0] AUDIO_PLAY ok < 23.719> [eDVBVideo] Video Device: /dev/dvb/adapter0/video0 < 23.719> [eDVBVideo] demux device: /dev/dvb/adapter0/demux0 < 23.719> [eDVBVideo0] VIDEO_SET_STREAMTYPE 1 - ok < 23.719> [eDVBVideo0] DMX_SET_PES_FILTER pid=0x0451 ok < 23.719> [eDVBVideo0] DEMUX_START ok < 23.719> [eDVBVideo0] VIDEO_FREEZE ok < 23.719> [eDVBVideo0] VIDEO_PLAY ok < 23.725> [eDVBText0] DMX_SET_PES_FILTER pid=0x0519 ok < 23.725> [eDVBText0] DEMUX_START ok < 23.727> [eDVBVideo0] VIDEO_SLOWMOTION 0 ok < 23.727> [eDVBVideo0] VIDEO_FAST_FORWARD 0 ok < 23.727> [eDVBVideo0] VIDEO_CONTINUE ok < 23.728> [eDVBAudio0] AUDIO_CONTINUE ok < 23.728> [eDVBAudio0] AUDIO_CHANNEL_SELECT 0 ok < 23.728> [eDVBTeletextParser] Starting! < 23.728> [eDVBTeletextParser] disable teletext subtitles page ffffffffffffffff (und) < 23.728> [eDVBPESReader] Created. Opening demux < 23.728> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.728> [eDVBTeletextParser] created teletext subtitle PES reader! < 23.728> [eDVBPESReader] Created. Opening demux < 23.728> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.728> [eDVBTeletextParser] starting PES reader on pid=0519 < 23.728> [eDVBPESReader] DMX_SET_PES_FILTER pid=0519 < 23.741> [eDVBCAService] new service 1:0:16:451:3E9:2174:EEEE0000:0:0:0: < 23.741> [eDVBCAService] add demux 0 to slot 0 service 1:0:16:451:3E9:2174:EEEE0000:0:0:0: < 23.741> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.741> [eDVBSectionReader] DMX_SET_FILTER pid=0 < 23.742> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.742> [eDVBSectionReader] DMX_SET_FILTER pid=18 < 23.743> [Notifications] RemovePopup, id = ZapError < 23.744> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.744> [eDVBSectionReader] DMX_SET_FILTER pid=0 < 23.826> [eDVBServicePMTHandler] PATready < 23.826> [eDVBServicePMTHandler] use pmtpid 0771 for service_id 0451 < 23.826> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.826> [eDVBSectionReader] DMX_SET_FILTER pid=1905 < 23.827> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.827> [eDVBSectionReader] DMX_SET_FILTER pid=0 < 23.828> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.828> [eDVBSectionReader] DMX_SET_FILTER pid=4352 < 23.828> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.828> [eDVBSectionReader] DMX_SET_FILTER pid=17 < 23.915> [eDVBServicePlay] eventNewProgramInfo timeshift_enabled=0 timeshift_active=0 < 23.916> [eDVBServicePlay] have 1 video stream(s) (0451), and 1 audio stream(s) (04b5), and the pcr pid is 1ffe, and the text pid is 0519 < 23.916> [eTSMPEGDecoder] decoder state: play, vpid=0451, apid=04b5 < 23.927> [eDVBCIInterfaces] gotPMT < 23.928> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.928> [eDVBSectionReader] DMX_SET_FILTER pid=1905 < 23.929> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 23.929> [eDVBSectionReader] DMX_SET_FILTER pid=1901 < 23.976> [eDVBServicePMTHandler] sdt update done! < 24.069> [eDVBServicePlay] timeshift < 24.069> [eDVBDemux] open demux /dev/dvb/adapter0/demux0 < 24.069> [eDVBSectionReader] DMX_SET_FILTER pid=18 < 24.604> [eDVBVideo0] VIDEO_GET_EVENT FRAME_RATE_CHANGED 25000 fps < 24.604> [eDVBVideo0] VIDEO_GET_EVENT SIZE_CHANGED 528x576 aspect 3 < 24.610> [eDVBVideo0] VIDEO_GET_EVENT PROGRESSIVE_CHANGED 0 < 25.069> [eDVBServicePlay] timeshift < 25.112> [VideoHardware] setting aspect: 16:9 < 25.112> [VideoHardware] setting wss: auto < 25.112> [VideoHardware] setting policy: panscan < 25.112> [VideoHardware] setting policy2: letterbox < 25.715> [eEPGCache] start caching events(1516501135) < 25.715> [eDVBSectionReader] DMX_SET_FILTER pid=3842 < 25.716> [eDVBSectionReader] DMX_SET_FILTER pid=3003 < 25.716> [eDVBSectionReader] DMX_SET_FILTER pid=18 < 25.717> [eDVBSectionReader] DMX_SET_FILTER pid=18 < 25.717> [eDVBSectionReader] DMX_SET_FILTER pid=18 < 25.717> [eDVBSectionReader] DMX_SET_FILTER pid=700 < 25.717> [eDVBSectionReader] DMX_SET_FILTER pid=700 < 25.718> [eDVBSectionReader] DMX_SET_FILTER pid=5000 < 25.718> [eDVBSectionReader] DMX_SET_FILTER pid=5000 < 25.718> [eDVBSectionReader] DMX_SET_FILTER pid=57 < 32.718> [eEPGCache] abort non avail virgin nownext reading < 32.719> [eEPGCache] abort non avail virgin schedule reading < 32.719> [eEPGCache] abort non avail netmed schedule reading < 32.720> [eEPGCache] abort non avail netmed schedule other reading < 32.720> [eEPGCache] abort non avail FreeSat schedule_other reading < 32.720> [eEPGCache] abort non avail viasat reading < 32.751> [eEPGCache] nownext finished(1516501142) < 32.771> [Task] job Components.Task.Job name=SoftcamCheck #tasks=1 completed with [] in None < 33.200> [eHdmiCEC] received message 84 00 00 00 < 33.512> [eHdmiCEC] received message 87 08 00 46 < 33.738> [eHdmiCEC] received message A0 08 00 46 00 04 00 01 < 33.963> [eHdmiCEC] received message A0 08 00 46 00 08 00 00 < 35.420> [eEPGCache] schedule finished(1516501145) < 37.492> [eEPGCache] schedule other finished(1516501147) < 37.493> [eEPGCache] stop caching events(1516501147) < 37.493> [eEPGCache] next update in 60 min < 58.989> [eInputDeviceInit] 1 8b 1 < 58.990> [InfoBarGenerics] KEY: 139 MENU < 58.990> [ActionMap] InfobarMenuActions mainMenu < 58.994> [Skin] processing screen Menu: < 59.007> [Skin] processing screen MenuSummary: < 59.391> [eInputDeviceInit] 2 8b 1 < 59.392> [InfoBarGenerics] KEY: 139 MENU < 59.407> [eInputDeviceInit] 0 8b 1 < 59.407> [InfoBarGenerics] KEY: 139 MENU < 80.839> [Console] command: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda') < 80.839> [eConsoleAppContainer] Starting sdparm < 81.407> [Console] finished: ('sdparm', 'sdparm', '--flexible', '--readonly', '--command=stop', '/dev/sda') < 104.600> [Console] finished: /usr/bin/ntpdate-sync < 104.600> [NetworkTime] setting E2 time: 1516531589.55 <------------------------------- 10:46:29 21/01/2018 81 seconds have elapsed < 128.648> [eInputDeviceInit] 1 ae 1 < 128.649> [InfoBarGenerics] KEY: 174 EXIT
However, the syslog (messages) shows a slightly different story:
There is an ntpdate update shown at 10:45:59 which is some 30 seconds before the update shown in the debug log. It would appear to me that ntpdate is being fired twice at least during the boot phase.Code:Jan 21 02:18:46 mutant51 user.info kernel: [ 12.586151] wlan0: authenticated Jan 21 02:18:46 mutant51 user.info kernel: [ 12.590497] wlan0: associate with f4:f2:6d:9b:fd:5a (try 1/3) Jan 21 02:18:46 mutant51 user.info kernel: [ 12.599991] wlan0: RX AssocResp from f4:f2:6d:9b:fd:5a (capab=0x431 status=0 aid=2) Jan 21 02:18:46 mutant51 user.info kernel: [ 12.650585] wlan0: associated Jan 21 02:18:46 mutant51 user.info kernel: [ 12.653640] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready Jan 21 02:18:46 mutant51 daemon.info avahi-daemon[2071]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999). Jan 21 02:18:46 mutant51 daemon.info avahi-daemon[2071]: Successfully dropped root privileges. Jan 21 02:18:46 mutant51 daemon.info avahi-daemon[2071]: avahi-daemon 0.6.32 starting up. Jan 21 02:18:46 mutant51 daemon.err avahi-daemon[2071]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory Jan 21 02:18:46 mutant51 daemon.warn avahi-daemon[2071]: WARNING: Failed to contact D-Bus daemon. Jan 21 02:18:46 mutant51 daemon.info avahi-daemon[2071]: avahi-daemon 0.6.32 exiting. Jan 21 02:18:53 mutant51 daemon.crit automount[2039]: key "logs" not found in map source(s). Jan 21 10:45:59 mutant51 daemon.notice ntpdate[2171]: step time server 193.1.31.66 offset 30374.856716 sec <---------------------------- this update not shown in debug log Jan 21 10:45:59 mutant51 daemon.notice stb-hwclock: Current system time has been written into FP pseudo RTC. Jan 21 10:46:29 mutant51 daemon.notice ntpdate[2200]: adjust time server 193.1.31.66 offset -0.000560 sec <--------------------------------- this matches the entry shown in debug log Jan 21 10:46:29 mutant51 daemon.notice stb-hwclock: Current system time has been written into FP pseudo RTC. Jan 21 11:16:35 mutant51 daemon.notice ntpdate[3460]: adjust time server 193.1.31.66 offset -0.011561 sec Jan 21 11:16:35 mutant51 daemon.notice stb-hwclock: Current system time has been written into FP pseudo RTC.
Either way, the asynchronous nature of establishing the time is messing with the evaluation of things like ABM and CrossEPG timer checks which happen at about 16 - 18 seconds into the debug log which is some 5 seconds before ntpdate-sync is being run. The log filename is using the stored fake-hwclock time.
I agree with you that somehow the clock setting needs to be synchronous and that checks for ABM and recording timers need to wait until the time is established.
GB Quad Plus, Mut@nt HD51, AX HD61, 80cm dish and Supreme Dark motor. Sony STR-DN 1060, Sony UHP-H1 Bluray, Odroid N2+ (CoreElec), Monitor Audio Bronze 5.1 speakers