Vix 5.1.006. Time wrong

[abu baniaz]

The real issue here is how it ever gets a future time set.

Wasn't that answered before? Two operations.

 

[Ashley69]

I presume this issue is still ongoing.
I changed my time sync to ntp because of the incorrect time being shown when on transponder sync and this seemed to fix the issue.
However when my box woke from deep standby this morning it had the incorrec time. (ntp sync)
A reboot has now brought in the correct time.
I presume if I had waited (sync set to very 30 mins)30 mins it would have corrected the time.
The box is a Mutant HD51
Image 5.1.011

 

[Joe_90]

@birdman - I've posted twice on the other bug thread about how ntpdate is being started twice at the same time, then updates the clock with the offset twice, thus moving the time into the future. I think your presumption that ntpdate uses an absolute time is not correct. My understanding is that ntpdate (like ntpd) retrieves a timestamp from a remote server after initially taking a local timestamp, then calculates the round trip delay etc., works out a difference and either applies that to the system clock by a set or a slew. I'm assuming that in the case of the double start of ntpdate one is picking up the result of the other and applying it twice. Don't forget that my timeserver is on the LAN and the round-trip delay is only a millisecond or so.

 

[birdman]

I think your presumption that ntpdate uses an absolute time is not correct.

I think it sets one. Easy enough to check that, though.

I'm assuming that in the case of the double start of ntpdate one is picking up the result of the other and applying it twice.

It was the future fake_hwclock that was the issue, but I'd forgotten that you had a double advance.

Perhaps ntp should be taking its own lock when it working....given that there is nothing else to stop it being run twice on any system. It shoudln't be relying on any external mutex mechanism.

 

[Joe_90]

I now have an ntpdate-sync script which runs ntpdate in the background when called from enigma2, but in the foreground if called when an interface is brought up (i.e. METHOD is set).
The former is needed to ensure that the time is set before services start (the whole point of the original change) and the latter is needed as enigma2 runs it using Console.ePopen(), and the Vix spinner pops up if that doesn't complete in <5s(?), which it usually won't.

This is it:
View attachment 55805

@birdman - I installed your script change and shut the box down and pulled the power overnight. This morning I started up but ntpdate-sync is not updating my system time at all now. It appears to be running but it's not changing the system clock time which started from the fake-hwclock.data of 07.30 set last night.

 

[Joe_90]

I think it sets one. Easy enough to check that, though.

It was the future fake_hwclock that was the issue, but I'd forgotten that you had a double advance.

Perhaps ntp should be taking its own lock when it working....given that there is nothing else to stop it being run twice on any system. It shoudln't be relying on any external mutex mechanism.

The future fake-hwclock is the result of ntpdate being run twice at the same time and corrupting the system clock. Then the stored false future value in fake-hwclock.data carries forward into the next boot and so on.

ntpd on a linux system generally runs on its own and is never initiated or run by user processes. On a linux system ntpdate is only run once at startup and even that is deprecated in favour of running ntpd with a flag to step the system time once at boot, then slew time subsequently. SpaceRat was trying to do similar with ntpdate

 

[Joe_90]

No. It has a check to ensure it isn't being run twice at the same time, but that is only done if the /usr/bin/lockfile-create exists, which it doesn't by default on OpenVix.

That's a deliberate design feature, although I forget why.
It's configurable by uncomment the line in /etc/default/fake-hwclock.

I didn't realise that feature was there (to enable fake-hwclock to be set in the past). I'll enable it now!

So I see from your reply that the check for double running of ntpdate-sync does not work on Vix because the lockfile creation mechanism doesn't work? That would explain my issues with double clock adjustment.

 

[birdman]

@birdman - I installed your script change and shut the box down and pulled the power overnight. This morning I started up but ntpdate-sync is not updating my system time at all now. It appears to be running but it's not changing the system clock time which started from the fake-hwclock.data of 07.30 set last night.

What happens if you login and run the script on the command line?

Odd that it works for for me. I've just booted up my box, which started with a time of 02:00:43 (last shutdown) but by the time enigma2 started its log was Enigma2_debug_2018-01-18_16-46-12.log - i.e. the time had been corrected using ntp.

I'm actually using a version with some debug code in it. This is it:
View attachment ntpdate-sync.zip
It will log when it runs to syslog (so /var/log/messages - except the first runs, which are before syslog starts) and also log the trace of its runs to /var/tmp/gml.log (which starts anew on each reboot).
The latter in particular should show what is (not) happening.

I presume that you've made the script executable (otherwise it won't be run...)?

 

[SpaceRat]

Out of interest. What happens if the box isn't networked at all and is just being used as a stand alone broadcast receiver/PVR?

The box will always start with the last shutdown (or image build time) during early boot.

Later at boot it tries an NTP sync, which is perfectly ok to fail.
If it succeeds, the box now has the accurate time set, if it fails, it will continue with last shutdown time (or image build time) plus some seconds since fake-hwclock was restored.

At the end, E2 starts up and syncs time again, either using DVB or using NTP, depending on what's set.
The problem is, that ntpdate-sync runs without locks against multiple concurrent runs at once which can lead to double adjustments.

 

[SpaceRat]

Also, the fact that fake-hwclock.data does not get updated once it has a value into the future is another issue.

That's why I asked if you use oscam.
oscam's "CLOCKFIX" would do exactly that: It prevents time adjustments to "past" times. CLOCKFIX = Forward ever, backward never!

Afaik, the oscams from ViX feed are now built without the CLOCKFIX (Which is actually a CLOCKBREAK), but most oscams from other sources are built with CLOCKBREAK.

 

[SpaceRat]

[Why doesn't fake-hwclock doesn't restore time if it's earlier than current time]
That's a deliberate design feature, although I forget why.

Because it "can't be".

As long as you don't own a time machine (or a compatible telephone cell), you can't start up your box any earlier than its latest previous shutdown
So the Pseudo-RTC inside the front panel will always
- either be ahead, because it continued to count ticks/time while the last shutdown time is at least n seconds earlier, where n is the time needed for the reboot. n can even become hours, days, weeks, ..., if your box went to deep-standby after the last shutdown, but the "RTC" will always be ahead of the last shutdown time, as long as the RTC really continued counting.
- or the RTC will be somewhere near 0 if the box was fully powered off (Then the RTC doesn't continue counting and gets reset to 0 = 1970-01-01 0:00 UTC) or even contantly be 0 (For some boxes that don't have an FP-RTC at all or no access to it from Linux).

The real issue here is how it ever gets a future time set.

Indeed.
The root cause is that the clock gets advanced twice.

 

[birdman]

Later at boot it tries an NTP sync, which is perfectly ok to fail.
If it succeeds, the box now has the accurate time set, if it fails, it will continue with last shutdown time (or image build time) plus some seconds since fake-hwclock was restored.

At the end, E2 starts up and syncs time again, either using DVB or using NTP, depending on what's set.

Those statements are incorrect as, with the current script, the ntpdate-sync is run in the background. Hence £2 (and all other services) can actually start with the fake-hwclock, not the correct one as set by ntp.
Hence my change to the ntpdate-sync script to run ntpdate in the foreground when an interface is brought up. This also prevents the two initial ntpdates from running together, as the first one (interface up) is run in the foreground so completes before E2 starts wherupon it may run another (which will run in the background to avoid the Vix spinner showing).

 

[SpaceRat]

Those statements are incorrect

No, it's not, ...

as, with the current script, the ntpdate-sync is run in the background. Hence £2 (and all other services) can actually start with the fake-hwclock, not the correct one as set by ntp.

... although this is also not incorrect.

The two explanations are completely compatible ...

If the initial ntpdate-sync fails (or takes long), E2 will start with the fake-hwclock time, just like you said.
That's absolutely no problem at all though, as it will later do some own time sync (Either DVB or NTP) anyways and previously E2 sometimes even started on 1970-01-01 and had no problem with it.

The only problem is that currently two sync can happen at the very same time.

Hence my change to the ntpdate-sync script to run ntpdate in the foreground when an interface is brought up. This also prevents the two initial ntpdates from running together, as the first one (interface up) is run in the foreground so completes before E2 starts wherupon it may run another (which will run in the background to avoid the Vix spinner showing).

That would indeed most probably solve the "two instances at once" issue at boot time, but it's
- only a quirky workaround
- slowing down boot on non-networked or slowly connecting boxes extremely
- will not prevent two instances of ntpdate-sync running at the same time under other circumstances (e.g. one ntpdate-sync run by cron and the other by E2)

There is an easy and clean solution:
Adding the lockfile-progs that are already anchored in ntpdate-sync will prevent concurrent runs of ntpdate-sync under all conditions and ntpdate-sync can stay backgrounded.

 

[twol]

No, it's not, ...


... although this is also not incorrect.

The two explanations are completely compatible ...

If the initial ntpdate-sync fails (or takes long), E2 will start with the fake-hwclock time, just like you said.
That's absolutely no problem at all though, as it will later do some own time sync (Either DVB or NTP) anyways and previously E2 sometimes even started on 1970-01-01 and had no problem with it.

The only problem is that currently two sync can happen at the very same time.



That would indeed most probably solve the "two instances at once" issue at boot time, but it's
- only a quirky workaround
- slowing down boot on non-networked or slowly connecting boxes extremely
- will not prevent two instances of ntpdate-sync running at the same time under other circumstances (e.g. one ntpdate-sync run by cron and the other by E2)

There is an easy and clean solution:
Adding the lockfile-progs that are already anchored in ntpdate-sync will prevent concurrent runs of ntpdate-sync under all conditions and ntpdate-sync can stay backgrounded.

„There is an easy and clean solution:
Adding the lockfile-progs that are already anchored in ntpdate-sync will prevent concurrent runs of ntpdate-sync under all conditions and ntpdate-sync can stay backgrounded.„

..... and how is that done ...or have I just missed it in all these conversations?

 

[SpaceRat]

..... and how is that done ...or have I just missed it in all these conversations?

That needs to be done by the image makers.
I'm currently testing the necessary changes.

 

[Joe_90]

That's why I asked if you use oscam.
oscam's "CLOCKFIX" would do exactly that: It prevents time adjustments to "past" times. CLOCKFIX = Forward ever, backward never!

Afaik, the oscams from ViX feed are now built without the CLOCKFIX (Which is actually a CLOCKBREAK), but most oscams from other sources are built with CLOCKBREAK.

I don't use OSCAM - in fact I do not use any CAM as all my viewing is free-to-air. Unless there is some default CAM installed and active by default...

 

[Joe_90]

What happens if you login and run the script on the command line?

Odd that it works for for me. I've just booted up my box, which started with a time of 02:00:43 (last shutdown) but by the time enigma2 started its log was Enigma2_debug_2018-01-18_16-46-12.log - i.e. the time had been corrected using ntp.

I'm actually using a version with some debug code in it. This is it:
View attachment 55806
It will log when it runs to syslog (so /var/log/messages - except the first runs, which are before syslog starts) and also log the trace of its runs to /var/tmp/gml.log (which starts anew on each reboot).
The latter in particular should show what is (not) happening.

I presume that you've made the script executable (otherwise it won't be run...)?

Yes - it's executable. First thing I checked when I FTP'd it. The script is running as it is being logged. It's just that the clock is not being updated. I reverted to the "update by transponder" setting around midday and shut down and my afternoon (16:50) boot and ABM/CrossEPG PowerTimer jobs ran ok.

 

[Joe_90]

The box will always start with the last shutdown (or image build time) during early boot.

Later at boot it tries an NTP sync, which is perfectly ok to fail.
If it succeeds, the box now has the accurate time set, if it fails, it will continue with last shutdown time (or image build time) plus some seconds since fake-hwclock was restored.

At the end, E2 starts up and syncs time again, either using DVB or using NTP, depending on what's set.
The problem is, that ntpdate-sync runs without locks against multiple concurrent runs at once which can lead to double adjustments.

That's definitely an issue as this has happened to me several times, pushing my clock into the future.

 

[Joe_90]

I didn't realise that feature was there (to enable fake-hwclock to be set in the past). I'll enable it now!

So I see from your reply that the check for double running of ntpdate-sync does not work on Vix because the lockfile creation mechanism doesn't work? That would explain my issues with double clock adjustment.

I'm replying to my own post - bear with me! I've uncommented the line in /etc/default/fake-hwclock which I thought would allow the system time to be stored (even if in the past) at shutdown. What this actually do is not allow the clock setting to be saved as I thought, but it stores zeroes so at the next boot the system thinks it's back at the unix epoch time of 1/1/70.... Explanation please

 

[Joe_90]

Now, with the system booting with a time of zero (1/1/170 01:00:00) what appears to be happening is that NTP is failing initially (because the WiFi network is not ready) so the system enables (temporarily) time setting by transponder. The box loads the stored transponder (in my case it's a local DTT channel) and stores the correct time. Shortly after, ntpdate-sync (or ntpdate) manages to get a valid time from an NTP server and the time is updated again.

I think that what was happening when fake-hwclock.data had a plausible time set, then when ntpdate failed to work initially, the time was unchanged. Only when ntpdate (or ntpdate-sync) was run 30 minutes later could the time be updated correctly. It didn't matter that the transponder had an accurate time - it couldn't be corrected because it was either different from the system time by more than 120 seconds or something else...

The probable solution for me, then, is to ensure that updates to /etc/default/fake-hwclock are commented out. I'll monitor carefully! Again - I've no issues with my GB Quad+ which is NTP synced and is hard-wired. This may be a WiFi - specific issue.

Maybe this is the better default setting for Vix builds at the moment?




EDIT - I've noticed that the ntpdate updates are not being logged in "messages" for some reason (so I can't tell which NTP server is being used). The E2 log is reporting ntpdate-sync at the 30 minute intervals as follows:

<  1833.285> [NetworkTime] Updating
<  1833.286> [Console] command: /usr/bin/ntpdate-sync
<  1833.286> [eConsoleAppContainer] Starting /bin/sh
<  1833.303> [Console] finished: /usr/bin/ntpdate-sync
<  1833.303> [NetworkTime] setting E2 time: 1516315624.3