T4 Recording Startup/Shutdown problem: After Event - Auto

[mjd]

Hi, I am having a problem with timer events from a Shutdown state, where the recordings work but my T4 remains fully on during and after.

1. Transponder Time: Shutdown > Boots ~5 minutes before > Full on > Records > Stays fully on.

* when first starts up date/time is wrong: 1 Jan 1970, 11:00 am. 2-15 seconds later it picks up the correct date/time from broadcast.

2. NTP (Ethernet): Shutdown > Boots ~5 minutes before > Full on for ~10 seconds > Standby > Records > Shutdown.

* correct behaviour.

I had been using method 1 successfully - where it shuts down after the recording ends - for a few months, but it stopped working about 2 months ago. I applied the 16.1 image but that didn't help. I don't normally have the Ethernet cable connected as it goes across the living room. I have tried a factory reset (not restoring settings) and also using NTP setting but without connecting the cable (result same as method 1). Does anyone have any suggestions on what is wrong or what to try?
Thanks, Michael.

[MrQuade]

What version of software is running on your front panel?

Older versions suffered from clock drift while in deep standby, which could lead to early wake-ups and thus the T4 not realising it had been woken for a recording, and thus not automatically resuming last state after the recording finishes.

The T4 front panel is supposed to be able to flag the T4 that it was woken for a recording, and the T4 should act accordingly, but perhaps this is not working in this instance. (The T2 doesn't have that flagging capability/feature).

Also, I couldn't say why NTP and transponder time behave differently either.

[Grumpy_Geoff]

As MrQuade advises, the clock drift issue was fixed with front panel version 20055 (and the later 20057) - are you still running 20052 (MENU > Information > About)?
See "Front panel update - V20057" - viewtopic.php?f=45&t=9962

[mjd]

Front panel is version 20057. I tried updating using the plugin, but it says this is the current version. Is there a way to re-apply the front panel firmware?

[MrQuade]

Front panel is version 20057. I tried updating using the plugin, but it says this is the current version. Is there a way to re-apply the front panel firmware?

No need. If it says 20057, it is 20057.

[prl]

...
1. Transponder Time: ...

* when first starts up date/time is wrong: 1 Jan 1970, 11:00 am. 2-15 seconds later it picks up the correct date/time from broadcast.
...

That is also normal behaviour apart from the time of day. When the PVR boots, system time is 0, and that corresponds to 00:00 1 Jan 1970. In the eastern states, that should be interpreted as 10:00 1 Jan 1970 (not 11:00) when DST isn't active (like now).

When the tuners have started up and the broadcast time date is detected in the broadcast stream, the time should be set to the correct time.

I'm not sure why Auto isn't shutting down, though.

I'll do some experimentation tomorrow.

[mjd]

That's interesting... My T4 starts up without ethernet cable with time date of 11:00:5x Thu 1 Jan 1970. I have Timezone set to (gmt+10:00) Hobart.

With ethernet cable it starts up with todays time date.

I just did further tests with Sync time using = Transponder Time: With ethernet cable in, success. Remove cable, failure (no standby, no shutdown). Changed nothing else!

Thanks for trying to help.

[prl]

That's interesting... My T4 starts up without ethernet cable with time date of 11:00:5x Thu 1 Jan 1970. I have Timezone set to (gmt+10:00) Hobart.

I wasn't thinking about DST quite right. While it's not summer now, it was on 1 Jan 1970 Tasmania was the only state/territory to have DST in 1970. So 00:00 1 Jan 1970 UTC is correctly 11:00 1 Jan 1970 local time in Tasmania and 10:00 1 Jan 1970 elsewhere in Australia.

With ethernet cable it starts up with todays time date.

I just did further tests with Sync time using = Transponder Time: With ethernet cable in, success. Remove cable, failure (no standby, no shutdown). Changed nothing else!
...

I can reproduce all of that. The key with the Ethernet connection (actually Internet connection) is that even if you aren't configured to use NTP for time, just before the enigma2 application starts (which runs most of the PVR functions), its startup script runs 'ntpdate' to set the time to the right setting. If there's no Internet connection that will fail and the correct time won't be set until the tuners have started up.

The question now becomes one of what part of the early startup code in enigma2 that decides whether to run in standby and whether to shut down when the recording finishes depends on the time being set correctly.

I'll have a look at it.

[prl]

The problem is that early in startup, there's a test to see whether the wakeup is for a recording timer with "auto" set for its "after" event.

That's done by checking that at the last shutdown, the next wakeup event was for for a recording timer with "auto" set, that the startup is due to a timer wakeup, and that the next recording will start within the next 3 minutes.

This all happens about 10 sec before the time can be set from the broadcast time.

If the time hasn't been set correctly by ntpdate before enigma2 runs, that time test will fail by a very large margin.

The current test in Navigation.__init__() is:

Code: Select all

		if getFPWasTimerWakeup():
			self.__wasTimerWakeup = True
			if nextRecordTimerAfterEventActionAuto and abs(self.RecordTimer.getNextRecordingTime() - time()) <= 360:
				# 										 ^^^^^^ Wrong time!
				# It's a wakeup for an "auto" record timer

I'm not convinced that the time test isn't simply a "belt and braces" type test and that a test on nextRecordTimerAfterEventActionAuto wouldn't be enough on its own.

If not, it can probably be replaced by another test that does not rely on the current time:

Code: Select all

		if getFPWasTimerWakeup():
			self.__wasTimerWakeup = True
			nextRecTime = self.RecordTimer.getNextRecordingTime()
			if (
				nextRecordTimerAfterEventActionAuto and
				self.RecordTimer.isNextRecordAfterEventActionAuto() and
				nextRecTime < self.RecordTimer.getNextZapTime() and
				nextRecTime < self.PowerTimer.getNextPowerManagerTime() and
				nextRecTime < Components.PluginComponent.plugins.getNextWakeupTime()
			):
				# It's a wakeup for an "auto" record timer

[prl]

The workaround, for the moment, is to make sure that the T3 or T4 is connected to the Internet at startup time. This can't be a problem on the T2 because "auto" recordings don't work properly on it at all (it has no hardware support to detect whether startup was from a timer).

[mjd]

Thank you. I guess this means most people connect their devices to the internet. I will need to run an ethernet cable under the house - I have been meaning to - also connect ps3 and future smart tv and/or ps4.

I bought my T4 in late November 2016 and it worked for a few months... was there a change in code around Feb/Mar this year? Maybe delay startup until correct time date, either ntp or broadcast, has been established?

[MrQuade]

Thank you. I guess this means most people connect their devices to the internet.

Maybe not necessarily specifically the Internet, but most definitely your home network (which is most often connected to the Internet).

Most of the reason I use the Beyonwiz PVRs rather than other brands, are for it's network capabilities, for sharing recordings and for streaming live TV to mobile equipment.

[prl]

Yes, but "auto" recordings should still work when there's no internet access.

[Grumpy_Geoff]

Is it possible this is an issue new to the 16.1 series firmware - as that is when the startup script began to do an ntp update (/usr/sbin/ntpdate) before starting enigma2.
Is it possible that attempted time update on a non internet-enabled unit sets the '1970' date, so it then subsequently fails the startup within 360 seconds check (before the transponder has been tuned, and time updated)?

Either that, or the startup is faster now, and due to the multi-threaded processing, it gets to the 'wakeup for timer' check quicker now than was previously the case, and also before the transponder time update can occur.

Would the system have previously grabbed the current time from the front panel?

[prl]

...
Would the system have previously grabbed the current time from the front panel?

According to the repository change logs, it was put into the enigma2.sh script, and then reverted.

The testing I've done today shows that the front panel RTC is reset to zero by a shutdown or reboot, so it wouldn't help.

[prl]

Is it possible this is an issue new to the 16.1 series firmware - as that is when the startup script began to do an ntp update (/usr/sbin/ntpdate) before starting enigma2.

I haven't found any changes to time setting in the 16.1 series firmware that would make this behave differently. That's not to say that there aren't any such changes. The setting of the time via NTP in /usr/bin/enigma2.sh is new in 16.1. The enigma2 binary runs ntpdate early in the Python startup (in mytest.py), so the addition of the ntpdate to enigma2.sh gives you the correct timestamp on log files created from a start from shutdown or a reboot, and if the network is available, prevents this problem when the system time is set from transponder time.

Is it possible that attempted time update on a non internet-enabled unit sets the '1970' date, so it then subsequently fails the startup within 360 seconds check (before the transponder has been tuned, and time updated)?

Not quite right. The system time is set to 0 at boot time. when ntpdate is run, that simply fails and leaves the system time at about 00:00:40 1 Jan 1970 UTC.

Either that, or the startup is faster now, and due to the multi-threaded processing, it gets to the 'wakeup for timer' check quicker now than was previously the case, and also before the transponder time update can occur.

I haven't noticed startup in the 16.1 firmware to have been much faster. Anyway, the test that's the cause of the problem happens in Navigation.__init__(). The Navigation instance is created quite early on in the startup, and in the only test where I checked the timing, the system clock is set from the broadcast stream about 10 sec later.

Would the system have previously grabbed the current time from the front panel?

As I said above, it did for a while in the OpenViX code, but I think that the inclusion and then the reversion of that code all happened during peteru's merges and it may never have been in any released Beyonwiz code. In any case, it appears it wouldn't have worked on the T series (and certainly not on my test T4), because the RTC seems to get cleared on shutdown and reboot.

This problem may also be an issue on T series boxes that use NTP time if, when the box starts from shutdown, the Internet is temporarily unavailable.

[prl]

I think I've found a way to defer the test for an "auto" recording shutdown to when the system time has been set by the transponder, if that's necessary. It's relatively straight-forward, because there's a callout available from the transponder time-setting object

[Grumpy_Geoff]

...
This problem may also be an issue on T series boxes that use NTP time if, when the box starts from shutdown, the Internet is temporarily unavailable.

Yep, you're right; same issue.

With network cable unplugged, it stays in the running state for the recording time and after.
- time not available
< 37.416> [Time By]: NTP
< 37.417> [eDVBLocalTimeHandler] invalid system time, refuse to disable transponder time sync
- zapping, popup infobar
< 72.247> [Navigation] playing 1:0:19:462:460:1012:EEEE0000:0:0:0:
< 72.490> [SCREENNAME] InfoBar
- time not yet set
< 72.609> [Console] finished: /usr/bin/ntpdate-sync
< 72.610> [NetworkTime] NO TIME SET
- tuning finished, can now get time from transponder
< 73.699> [eDVBLocalTimerHandler] dont have correction.. set Transponder Diff
< 73.699> [eDVBLocalTimerHandler] set RTC Time
< 73.699> [eDVBLocalTimerHandler] update RTC
< 73.699> [eDVBLocalTimerHandler] time update to 09:11:40
< 73.699> [eDVBLocalTimerHandler] m_time_difference is 1495415427
< 73.699> [eDVBLocalTimerHandler] set Linux Time
< 73.700> [eEPGCache] time updated.. start EPG Mainloop


With a network connection, it went to standby at 15 seconds after time was deemed available
- time available
< 50.536> [Time By]: NTP
< 50.538> [eDVBLocalTimeHandler] disable sync local time with transponder time!
- bootup for timer recording detected
< 59.964> [Navigation] RECTIMER: wakeup to standby detected.
- zapping, popup infobar
< 63.940> [Navigation] playing 1:0:19:462:460:1012:EEEE0000:0:0:0:
< 64.072> [SCREENNAME] InfoBar
- go to standby
< 74.965> [Navigation] TIMER: now entering standby
< 75.008> [Standby] enter standby

I bet you know all that anyway

[prl]

I'd read it in the code, but I hadn't actually tested it. It doesn't surprise at all.

[Star6key]

I came to grumble about this issue, but it seems that it happened to someone else.
2 days in a row I've had no internet access when the T4 booted up, leaving it with 1 Jan 1970 and missed recordings.
Not happy.

Is there anything we (as users) can do to prevent this from happening?

[MrQuade]

Is there anything we (as users) can do to prevent this from happening?

Two options.
Run your own NTP server and point the Wiz at that (I do this).
or
Switch to using transponder time if you are likely to have no Internet access at random times.

[prl]

I came to grumble about this issue, but it seems that it happened to someone else.
2 days in a row I've had no internet access when the T4 booted up, leaving it with 1 Jan 1970 and missed recordings.
...

I'm not sure that that's the same issue. I tested starting the T4 with no Ethernet, both using NTP for time setting and broadcast time, and while at the time of the test for whether the recording should be done in standby the system time is incorrect and that test fails, and the "auto" shutdown fails, the recordings do get made, and the time is set about 10 sec after that test was made.

That was also the OP's problem. The recordings were made when the Ethernet was disconnected, but the T4 didn't do the recordings in standby, it stayed fully running, and it didn't go back to shutdown when the recording finished.

Your issue may need its own topic.

[Star6key]

Two options.
Run your own NTP server and point the Wiz at that (I do this).
or
Switch to using transponder time if you are likely to have no Internet access at random times.

It's already using Transponder Time.

[MrQuade]

It's already using Transponder Time.

Are you able to repeat this reliably? Disconnect the T4 from the network and reboot, and it never gets the time from the transponder?

[Star6key]

It's already using Transponder Time.

Are you able to repeat this reliably? Disconnect the T4 from the network and reboot, and it never gets the time from the transponder?

Just shutdown the T4.
Disconnected the ethernet cable
Started the T4.
Brought up the epg - empty - Thu 1 Jan 1970 10.00 (I'm assuming the 10.00 is gmt + syd time).

I would say this is a pretty reliable repeat.

edit -
"Sync time using - Transponder Time" in the time settings.

edit 2 -
restarting the gui resets the time (after plugging in the ethernet cable).

[MrQuade]

Not getting time from the broadcaster?
You don't have an exotic RF setup at all? Just a roof antenna and receiving public broadcasts?

Does it happen on all channels?
As in, if you start up, and then change channels, does it still not get the time?

(But as prl says, this definitely sounds different, since prl has done the same test with different results to you, a new thread is probably warranted).

[prl]

...
(But as prl says, this definitely sounds different, since prl has done the same test with different results to you, a new thread is probably warranted).

I did the test yesterday as part of my response to the OP, and again today in response to Star6key's post, and I don't see what Star6key is getting. There must be some other element playing a part.

[Star6key]

I'll have to have a look tomorrow. Going to record 4 Corners & HYBPA.

[Grumpy_Geoff]

...
(But as prl says, this definitely sounds different, since prl has done the same test with different results to you, a new thread is probably warranted).

I did the test yesterday as part of my response to the OP, and again today in response to Star6key's post, and I don't see what Star6key is getting. There must be some other element playing a part.

My test also had the transponder time being used to set the system time when I had the network cable unplugged - viewtopic.php?f=50&t=11181#p153051

[Grumpy_Geoff]

It's already using Transponder Time.

Are you able to repeat this reliably? Disconnect the T4 from the network and reboot, and it never gets the time from the transponder?

Just shutdown the T4.
Disconnected the ethernet cable
Started the T4.
Brought up the epg - empty - Thu 1 Jan 1970 10.00 (I'm assuming the 10.00 is gmt + syd time).

I would say this is a pretty reliable repeat.

I'm wondering why the EPG was empty - shouldn't it have been initially loaded from the cache (previously written at restart/shutdown)?

Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

[MrQuade]

I'm wondering why the EPG was empty - shouldn't it have been initially loaded from the cache (previously written at restart/shutdown)?

I don't think the cache goes back as far as 1970 though . The "current time" would have been showing 1970, and the cache would have had content 47 years later. So he could have tried pressing CH+ about 17 thousand times .

Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

Good thought! I had a similar thought that if the T4 had started to a non-service )which is why I mentioned changing channel), but HDMI-IN didn't occur to me!
It might be worth setting a default service to one of the broadcast services if this is something that id likely to happen.

[Grumpy_Geoff]

I'm wondering why the EPG was empty - shouldn't it have been initially loaded from the cache (previously written at restart/shutdown)?

I don't think the cache goes back as far as 1970 though . The "current time" would have been showing 1970, and the cache would have had content 47 years later. So he could have tried pressing CH+ about 17 thousand times .

17,000 times - nah mate, just press TEXT and enter the date
You're likely right though, the EPG display couldn't be positioned to 1970.

[Star6key]

...Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

We have a wiener

I always have 'hdmi in' as the current station.

[prl]

Who's from Vienna?

Anyway, looks like Grumpy_Geoff hit it on the head. I'll check it tomorrow.

[Grumpy_Geoff]

...Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

We have a wiener

I always have 'hdmi in' as the current station.

As MrQuade posted, set a terrestrial service as the startup service - from live TV, press FAV to bring up the channel/service list, scroll to a service. then MENU > {number} Set as startup service.
Job done.

[Grumpy_Geoff]

Who's from Vienna?

Ultravox?
"This means nothing to me
Oh, Vienna"

[Star6key]

...Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

We have a wiener

I always have 'hdmi in' as the current station.

As MrQuade posted, set a terrestrial service as the startup service - from live TV, press FAV to bring up the channel/service list, scroll to a service. then MENU > {number} Set as startup service.
Job done.

Cheers.

Who's from Vienna?

Ultravox?
"This means nothing to me
Oh, Vienna"

Now that's my kind of music!

[prl]

... I'll check it tomorrow.

Confirmed. If there's no Ethernet connection and the current channel is a non-broadcast service like HDMI IN, the box starts up with the time as 00:00:00 1 Jan 1970 UTC. Which is 11:00:00 1 Jan 1970 UTC in Tasmania and 10:00:00 1 Jan 1970 UTC elsewhere on the east coast. Post-WWII DST didn't start in states other than Tasmania until after 1970.

[prl]

...Another thought I had as to why the transponder time wasn't being used - if HDMI-IN waa the laat service played, then there's not much chance of a transponder time being received.

We have a wiener

I always have 'hdmi in' as the current station.

As MrQuade posted, set a terrestrial service as the startup service - from live TV, press FAV to bring up the channel/service list, scroll to a service. then MENU > {number} Set as startup service.
Job done.

That's fine as a workaround. A more user-friendly solution might be to automatically change to a broadcast service if transponder time is needed to set the time and the startup channel isn't a broadcast service.

Transponder time is needed if there's no NTP service available at startup.

[MrQuade]

That's fine as a workaround. A more user-friendly solution might be to automatically change to a broadcast service if transponder time is needed to set the time and the startup channel isn't a broadcast service.

Transponder time is needed if there's no NTP service available at startup.

In Star6ky's case, he is almost always going to be on a non-broadcast service when the Wiz starts since he records from late-night HDMI sources quite frequently, so this workaround the extra check should not be necessary.

[prl]

That's fine as a workaround. A more user-friendly solution might be to automatically change to a broadcast service if transponder time is needed to set the time and the startup channel isn't a broadcast service.

Transponder time is needed if there's no NTP service available at startup.

In Star6ky's case, he is almost always going to be on a non-broadcast service when the Wiz starts since he records from late-night HDMI sources quite frequently, so this workaround the extra check should not be necessary.

I'm talking about a coded general solution to the problem, not a workaround for a specific instance.

[prl]

Bug #588: "Auto" recording timers sometimes not shutting down
Bug #589: System time setting from broadcast fails if startup service isn't a broadcast service

[prl]

Bug #588: "Auto" recording timers sometimes not shutting down
...

I have coded and tested a fix for this. I'll check that it's also a problem on OpenViX, and if so, test it there and submit it upstream as well as to the Beyonwiz repository.

[prl]

...
Bug #589: System time setting from broadcast fails if startup service isn't a broadcast service

I've coded a fix for this so that when the startup code is about to set the startup service (either last service played before shutdown or the user-selected startup service), if the system time hasn't been set and the startup service isn't a DVB service (e.g. HDMI IN), the startup service is changed to the first DVB service in the current bouquet.

That seems fairly robust, but it could be made a bit more robust by first looking for a DVB service in the current bouquet, and if that fails looking for one in another bouquet (and changing bouquets as well). The alternative bouquets search can't be done if the user has disabled Enable multiple bouquets.

That code would be more complicated than the current code, and would have the potential to change the user's bouquet.

[prl]

In fixing Bugs 588 & 589 I found another minor problem: if the system time isn't set by NTP in enigma2.sh, at the time that the infobar is first displayed, the correct time isn't yet set. That means that the event information in the infobar (now title and times, next title & times, progress bar and next duration) isn't displayed. It stays that way until the next "updated event info" event is generated in the low-level code, typically after a minute or so.

I've coded, but not yet tested, a fix for that. The fix is similar to the fix for Bug #588.

[MrQuade]

That means that the event information in the infobar (now title and times, next title & times, progress bar and next duration) isn't displayed. It stays that way until the next "updated event info" event is generated in the low-level code, typically after a minute or so.

Ahh, that might explain how ad only saw an empty progress bar on the front panel when he was having his initial setup issues here.

[prl]

That means that the event information in the infobar (now title and times, next title & times, progress bar and next duration) isn't displayed. It stays that way until the next "updated event info" event is generated in the low-level code, typically after a minute or so.

Ahh, that might explain how ad only saw an empty progress bar on the front panel when he was having his initial setup issues here.

Perhaps, but the issue I'm talking about resolves itself if you wait a bit (or change channels). I just want to make it a bit cleaner.

[MrQuade]

Perhaps, but the issue I'm talking about resolves itself if you wait a bit (or change channels). I just want to make it a bit cleaner.

I was just thinking that since it happened to ad on his initial boot, and he presumably skipped though the setup wizard, he wouldn't have had any network nor any services to tune to to update his clock either.

[prl]

Perhaps, but the issue I'm talking about resolves itself if you wait a bit (or change channels). I just want to make it a bit cleaner.

I was just thinking that since it happened to ad on his initial boot, and he presumably skipped though the setup wizard, he wouldn't have had any network nor any services to tune to to update his clock either.

If there haven't been any services scanned, the lack of now/next info in the infobar won't (can't) resolve itself.

But the infobar and front panel displays would have been similar to what happens temporarily in the case I described. IIRC I suggested in the original topic that the issue there might have been a failure to scan, or a failure of the scan.