Vix 5.1.006. Time wrong

[SpaceRat]

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

fake-hwclock is a 1:1 rip from Raspbian, the Debian distro for Raspberry Pis

 

[Joe_90]

It does, the pre-requisites for it just haven't been installed inside the image previously. I changed that yesterday.

I was referring to the ntpdate binary - not ntpdate-sync

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.

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.

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.

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?

 

[Joe_90]

fake-hwclock is a 1:1 rip from Raspbian, the Debian distro for Raspberry Pis

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.

 

[SpaceRat]

I was referring to the ntpdate binary - not ntpdate-sync

You have to see the whole package though

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.

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

However, I still have the situation where I'm getting a double forward of time. Is E2 still running an ntpdate call somewhere?

Yes.
If you set it to use NTP, is simply periodically calls ntpdate-sync ...

 

[dsayers]

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

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'

I deleted the prestart sh and enigma2 booted fine

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.

 

[birdman]

It does, the pre-requisites for it just haven't been installed inside the image previously. I changed that yesterday.

No, ntpdate doesn't have any locking. ntpdate-sync does (optionally), but that's just a front-end script. you can still run ntpdate by hand twice at the same time.

 

[birdman]

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.

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.

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.

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.

 

[birdman]

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.

Which is arguably a bug, as ntpdate-sync will have been run as the network interface is brought up, so it doesn't need to be run as enigma2 starts (transponder time does, though, as they may be no netwo0rk) - just the "run every 30mins from now" bit is needed.

 

[birdman]

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

It is confusing (it confused me). I wouldn't do it, but I didn't write the code. Once someone has written it it would be a potential maintenance probelm to change it just for one distro.

 

[Joe_90]

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.

<    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>[COLOR="#FF0000"] [Console] command: /usr/bin/ntpdate-sync                  <------------------------------------------- ntpdate-sync kicked off[/COLOR]
<    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
<  [COLOR="#FF0000"] 104.600> [NetworkTime] setting E2 time: 1516531589.55                <-------------------------------  10:46:29 21/01/2018       81 seconds have elapsed[/COLOR]
<   128.648> [eInputDeviceInit] 1 ae 1
<   128.649> [InfoBarGenerics] KEY: 174 EXIT

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.

However, the syslog (messages) shows a slightly different story:

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).
[COLOR="#FF0000"]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[/COLOR]
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.

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

 

[twol]

So your build will contain all current OEA „time fix“ commits - and you still have issues.

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

 

[Joe_90]

So your build will contain all current OEA „time fix“ commits - and you still have issues.

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

Yes - I waited to see his posts on GitHub before I kicked off the build yesterday and checked that he had updated OE 4.2 branch.

 

[birdman]

So would be nice if SpaceRat could layout a strategy for fixing this issue or at least layout what he is planning.

I think the current strategy is that I'm going to write a ntpdate-sync that optionally does the sync synchronously when a network comes up (that option being defined within the settings file).

The biggest issue here seems to be how long it takes for a Wifi interface to become usable (since wpa_supplicant needs to achieve that). I'll need to do some tests on a Wifi interface for that....

It would be nice if if-up.d scripts weren't run until an interface were up, running and usable - it may only check the first two.

 

[birdman]

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 did the reverse. Having done some programming in the early 70s I stopped, then ended up "accidentally" moving into programming in 1983, where I stayed for >30 years.

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.

I can't figure out that original 81s, although it is the second one to run that takes this time (i.e. the first one run by enigma2, rather than the earlier one run by the network interface star-up).

I've just been testing out adding a Wifi interface to my MBtwin. When I bring it up it is pingable (and usable) in ~2s. Likewise on my laptop (which send more info the the system logs) the Wifi seems to take 1.5s to get associated and ready (oddly, the Ethernet connexion takes 3s). Your syslog also shows your interface being ready quite quickly.

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.

As I've noted, there will be one ntpdate-sync as the network interface is brought up (and since you are running this in the background syslogd will be running by the time it completes, so it gets recorded). Then enigma2, as it start up, also runs a sync if you have configured the time to be set by ntp rather than from the transponders. I reckon this one is unneeded, given that the system will have just done one.

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.

 

[Joe_90]

I changed the NTP server entry to my local address (192.168.0.190) yesterday evening, just to get back to my "usual" configuration. This morning, I had the usual delayed setting of the system time. Snip from the syslog shows three time settings by ntpdate at start time. Only one setting (using ntpdate-sync) shown in the debug log with the same 80 second delay between call and return. Subsequent calls of ntpdate-sync seem to take about six seconds, but that may be because of the external pinging of google servers as an online check.

Jan 21 17:10:16 mutant51 user.info kernel: [   12.518925] wlan0: authenticate with f4:f2:6d:9b:fd:5a
Jan 21 17:10:16 mutant51 user.info kernel: [   12.547264] wlan0: send auth to f4:f2:6d:9b:fd:5a (try 1/3)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.568581] wlan0: authenticated
Jan 21 17:10:16 mutant51 user.info kernel: [   12.572457] wlan0: associate with f4:f2:6d:9b:fd:5a (try 1/3)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.582250] wlan0: RX AssocResp from f4:f2:6d:9b:fd:5a (capab=0x431 status=0 aid=4)
Jan 21 17:10:16 mutant51 user.info kernel: [   12.692383] wlan0: associated
Jan 21 17:10:16 mutant51 user.info kernel: [   12.695482] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: Found user 'avahi' (UID 999) and group 'avahi' (GID 999).
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: Successfully dropped root privileges.
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: avahi-daemon 0.6.32 starting up.
Jan 21 17:10:16 mutant51 daemon.err avahi-daemon[1982]: dbus_bus_get_private(): Failed to connect to socket /var/run/dbus/system_bus_socket: No such file or directory
Jan 21 17:10:16 mutant51 daemon.warn avahi-daemon[1982]: WARNING: Failed to contact D-Bus daemon.
Jan 21 17:10:16 mutant51 daemon.info avahi-daemon[1982]: avahi-daemon 0.6.32 exiting.
Jan 21 17:10:23 mutant51 daemon.crit automount[1950]: key "logs" not found in map source(s).
Jan 22 10:54:06 mutant51 daemon.notice ntpdate[2083]: step time server 192.168.0.190 offset 63785.191245 sec
Jan 22 10:54:20 mutant51 daemon.notice ntpdate[2093]: adjust time server 192.168.0.190 offset -0.000026 sec
Jan 22 10:54:49 mutant51 daemon.notice ntpdate[2113]: adjust time server 192.168.0.190 offset -0.000274 sec

 

[birdman]

I changed the NTP server entry to my local address (192.168.0.190) yesterday evening, just to get back to my "usual" configuration......

I've been thinking more about this (before actually doing anything). There is an issue with systems with multiple active interfaces - they will do an ntpdate sync for each one, which makes no sense. You really want to do it just once, after all interfaces are up*, but you'll never know when that is when being called from ifup. The only reliable way you can run after all interfaces have been started is to run it from a separate sysvinit script run imediately after the network starter (S10networking).



*You might have your DNS resolver reachable via the first interface and your NTP server via the last one. Or vice versa....

 

[Joe_90]

Hmmm - I disable the ethernet port interface during the install network wizard, but it's still physically present of course, so it may be firing multiple ntpdate syncs, but the ethernet port is not cabled to anything, so there shouldn't be any reply. I just thought that the three ntpdate responses within the same minute as shown in syslog in post #155 was a bit odd as they could only be satisfied on the WiFi interface.

 

[birdman]

Hmmm - I disable the ethernet port interface during the install network wizard, but it's still physically present of course

No. it has to be configured to come up.

I just thought that the three ntpdate responses within the same minute as shown in syslog in post #155 was a bit odd as they could only be satisfied on the WiFi interface.

When ntpdate-sync is called for an interface coming up it sends the -b option to ntpdate, which steps the time (sets it absolutely). At other times this isn't set, so the system clock is sped up/slowed down slightly to move it towards the real time in a continuously forward-advancing time manner.
So the second two settings which you have are not from ifup.

I suppose its possible(?) that this is happening, bearing in mind that all of your ntpdate-sync run in the background (which is, I reckon, a big part of your problem, although oddly no-one else seems to see it).

1. ifup brings up an interface and ntpdate-sync(1) runs. For some reason it takes a while...
2. enigma2 starts and fires up ntpdate-sync(2). It also schedules another one in 30 mins.
3. ntpdate-sync(1) completes and sets the time absolutely (advancing it by 17h 40+m).
4. The enigma2 scheduler sees that it's next ntpdate-sync run has passed (some 17h 10+m ago...) so fires off ntpdate-sync(3).
5. ntpdate-sync(2) finishes and slews the time
6. ntpdate-sync(3) finishes and slews the time

This is dependent on enigma2 using absolute time for timers; not a good idea if the time can change underneath you, but I suspect that the expectation (given that it is meant to be scheduling recordings by absolute time) is that the time is always correct - hence the need to ensure this before enigma2 starts.

 

[Joe_90]

Thanks @birdman. What you say about E2 firing off an ntpdate-sync and then the scheduler seeing the time advance by >30 minutes and firing another makes sense. Where does enigma2 call the ntpdate-sync script?
I know the difference between stepping and slewing the time from using ntpd on my linux machines. The first call to ntpd steps the system clock by the calculated offset from its current value. Subsequently, ntpd slews the system clock toward the actual time by varying the oscillator frequency. ntpdate has similar functions but is not quite as sophisticated as ntpd. SpaceRat has changed the behaviour of ntpdate by using stepping on the first call and slewing thereafter which makes sense.

 

[twol]

Guys, I learn something from all these posts, but it doesnt move fat—tony forward.
There is obviously an issue, which (I guess ) is WiFi related and unless Birdman can come up with a solution (which would be great), I really expect more from SpaceRat than silence on this public thread