[Mut@nt] HD51 OpenViX 5.1.032 will not return to standby/deep standby after recording

[Mickkie]

Hi All,

I'm not sure if this is a regression bug, because I also experienced this with 5.1.027. The box will wake up from deep standby to perform a recording. It will stay up, rather than going to standby during the recording and unfortunately will continue to stay up spinning its disk for ever after. The normal behaviour is to return to standby during the recording, and deep standby thereafter if it woke up from a deep standby.

I did a in-situ system update which started this problem and then re-flashed with a USB stick just in case, but the same symptoms remain.

Then I tried to return to a 5.1.030 backup image, but unfortunately this failed completely.

Is there a workaround to this problem?

 

[ccs]

Does this help.....

https://www.world-of-satellite.com/...er-a-recording&p=382929&viewfull=1#post382929

 

[Mickkie]

Thanks css,

No, the "Stop timeshift while recording?" was disabled anyway. However, I reflashed via USB and then I did NOT restore any settings from a back up. Of course I had to rescan channels and set afresh a lot of my settings and a couple of timers. The good news is that on an one-off timer the box woken up from Deep Standby, then went to Standby as it should do and it is presently recording. I'll wait to see what it does after the recording is finished, but would like to remain optimistic.

Perhaps there was a lot of cruft accumulated over multiple updates in situ and some settings we clashing.

 

[Mickkie]

OK, the device returned to Deep Standby after it finished recording. Therefore something in my previous settings must have caused the problem.

Is there a way to restore my timers without using a previous backup? I suspect if I restore from backed up settings I will merely bring back the problem along with my timers and settings.

 

[ccs]

You can extract timers.xml from a previous settings backup, stop enigma with the telnet command init 4, copy timers.xml to /etc/enigma2/ , and restart enigma with init 3.

 

[Mickkie]

Thanks css, very useful tip!

However, I'm at a loss as to what is happening with this box. When I test it to see if it wakes up, goes to Standby, records and shuts down, it behaves as it should. When I turn my back and leave it to record its auto-timers as it used to, it wakes up and stays on continuously! Is it worth capturing and posting a log in case it shows what is the cause of this problem?

 

[ccs]

Is this the same problem you reported here.....

https://www.world-of-satellite.com/...fter-recording&p=470374&viewfull=1#post470374

My ET10K is waking up from deep standby and recording in standby all the time at the moment, and shuts down to deep standby if after event is set to do that.

The only time it mis-behaved waking up a couple of months ago was when the time in deep standby was longer than usual (probably about 20 hours)

 

[cactikid]

Just a query if its an internal/external hdd or a usb passport?

 

[Mickkie]

Is this the same problem you reported here.....

https://www.world-of-satellite.com/...fter-recording&p=470374&viewfull=1#post470374

Yes, it is the same problem.

 

[Mickkie]

I have an 1TB internal spinning drive for recordings, timeshift and logs. I also have an external USB stick I bought from WoS at the same time I bought the box. Interestingly, I tried to fsck the USB fs with the GUI and it complained of an error. So I unmounted it manually and run fsck.vfat on it. fsck reported an error (probably it was not unmounted cleanly last time). Anyway, I thought the error was because of this, allowed the fsck command to remove a dirty bit from the previous unlean unmounting and following a quick test during which the box behaved correctly, I was hoping the error was fixed. It wasn't going to be that easy. Earlier this eve it played up again. So I'm at a loss as to what is causing all this. As I said, happy to post logs the next time it plays up, in case someone can spot what's amiss.

 

[cactikid]

i presume hdd to go into standby after 5 mins?

 

[ccs]

i presume hdd to go into standby after 5 mins?

hdd "standby"/spin down won't effect when/if the box goes into standby/deep standby.

 

[Mickkie]

In any case, HDD standby is set to 2 minutes:

config.usage.hdd_standby=120

 

[Mickkie]

I left the Mut@nt on Standby last night. Then things went really weird this morning ... An autotimer was recorded twice over.

The second instance of the recording started 1 minute later. Both recordings were complete. Following these recordings the Mut@ant went into Standby again.

Then another autotimer a couple of hours later also recorded a program twice. Again the two recordings were 1 minute apart from each other.

 

[Mickkie]

I started afresh. Reflashed with the 5.1.032 image, skipped the wizard and manually configured settings, scanned for services, scanned autobouquets, added a few favourites using the web GUI and a couple of autotimers. Then placed it in Deep Standby and waited ... it failed to go back into standby upon waking up for a recording. Comparing with earlier logs of when it was behaving correctly, the difference seems to take place after the timers are checked for conflicts. In the correctly working instance I can see this:

< 32.724> [Timer] Record RecordTimerEntry(name=Newsnight, begin=Fri Aug 10 22:29:00 2018, serviceref=1:0:19:4440:4084:233A:EEEE0000:0:0:0:, justplay=0, isAutoTimer=1)
< 32.737> [TimerSanityCheck] conflict not found!
< 32.737> [Timer] Record RecordTimerEntry(name=Weather for the Week Ahead, begin=Sat Aug 11 00:44:00 2018, serviceref=1:0:19:4484:4084:233A:EEEE0000:0:0:0:, justplay=0, isAutoTimer=1)
< 32.741> [Navigation] RECTIMER: wakeup to standby detected. <==
< 32.742> [ABM-main][AutoBouquetsMakerautostart] AutoStart Enabled
< 32.743> [ABM-main][AutoAutoBouquetsMakerTimer] Schedule Disabled at Fri 03 Aug 2018 11:24:31 BST
< 32.743> [CrossEPG_Auto] AutoStart Enabled
< 32.745> [CrossEPG_Auto] Schedule Disabled at Fri 03 Aug 2018 11:24:31 BST
< 32.746> [EPGImport] autostart (0) occured at 1533291871.88
< 32.746> [EPGImport] WakeUpTime now set to -1 (now=1533291871)
< 32.746> [ImageManager] AutoStart Enabled
< 32.746> [ImageManager] Backup Schedule Disabled at (now=Fri 03 Aug 2018 11:24:31 BST)
< 32.746> [BackupManager] AutoStart Enabled
< 32.746> [BackupManager] Backup Schedule Disabled at (now=Fri 03 Aug 2018 11:24:31 BST)

The above line is missing in the incorrectly behaving occurrence:

< 29.829> [Timer] Record RecordTimerEntry(name=Channel 4 News, begin=Thu Aug 9 18:57:00 2018, servi
ceref=1:0:19:4500:4084:233A:EEEE0000:0:0:0:, justplay=0, isAutoTimer=1)
< 29.831> [TimerSanityCheck] conflict not found!
< 29.832> [Timer] Record RecordTimerEntry(name=Channel 4 News, begin=Fri Aug 10 18:57:00 2018, serviceref=1:0:19:4500:4084:233A:EEEE0000:0:0:0:, justplay=0, isAutoTimer=1)
< 29.835> [ABM-main][AutoBouquetsMakerautostart] AutoStart Enabled
< 29.835> [ABM-main][AutoAutoBouquetsMakerTimer] Schedule Disabled at Fri 03 Aug 2018 18:44:57 BST
< 29.835> [CrossEPG_Auto] AutoStart Enabled
< 29.836> [CrossEPG_Auto] Schedule Disabled at Fri 03 Aug 2018 18:44:57 BST
< 29.836> [EPGImport] autostart (0) occured at 1533318297.12
< 29.836> [EPGImport] WakeUpTime now set to -1 (now=1533318297)
< 29.836> [ImageManager] AutoStart Enabled
< 29.836> [ImageManager] Backup Schedule Disabled at (now=Fri 03 Aug 2018 18:44:57 BST)
< 29.836> [BackupManager] AutoStart Enabled
< 29.836> [BackupManager] Backup Schedule Disabled at (now=Fri 03 Aug 2018 18:44:57 BST)

Other than this difference I can't see anything else standing out between the two log files.

 

[twol]

I know 0 about timers, but just wondered if you were using NTP or transponder to establish the system time (not that it should make a difference I guess)

 

[Mickkie]

I know 0 about timers, but just wondered if you were using NTP or transponder to establish the system time (not that it should make a difference I guess)

Thanks twol,
The missing log entry "[Navigation] RECTIMER: wakeup to standby detected." is pointing to the mechanism or processes running when the box wakes up from standby. So, something must be amiss with RECTIMER or whatever leads up to it. I have left the system time to sync with the transponder, but can try out an NTP server and see if this makes any difference.

 

[twol]

Thanks twol,
The missing log entry "[Navigation] RECTIMER: wakeup to standby detected." is pointing to the mechanism or processes running when the box wakes up from standby. So, something must be amiss with RECTIMER or whatever leads up to it. I have left the system time to sync with the transponder, but can try out an NTP server and see if this makes any difference.

Some time ago there were significant changes made to E2 (which Birdman helped to actually work) to resolve system time and thats why I was curious about your use (NTP would avoid any issues in this code)

 

[Mickkie]

I changed the time setting to sync with NTP and soon discovered that while in Deep Standby the system clock ... stops! So recordings are missed altogether. As soon as I restart the box manually the clock starts again but it won't jump to present time. Consequently, the clock is lagging by how long I left it in Deep Standby. More about this below, but first let me share a recent finding pertinent to the problem at hand:

While experimenting I discovered this behaviour which may be of importance. If I set a timer which is due to start soon, say within the next 10 minutes and place the box in Deep Standby, I get a warning that recordings are imminent. I proceed and place the box in Deep Standby regardless. Well, when it wakes up in a few minutes following such a warning, the box behaves as expected and the "[Navigation] RECTIMER: wakeup to standby detected." is present in the logs. If I set up a timer sometime longer in the future whereby I do not receive a warning when I place it in Deep Standby, the box misbehaves as per my original report.

Regarding the NTP problem, I thought initially the ntp server may be busy so I tried my local router's ntp server using its IP address, then tried 0.pool.ntp.org, 3.uk.pool.ntp.org and all failed to make the box keep up with, or adjust to present time. I haven't noticed such problems when using the transponder to set the system clock. The logs show E2 is obtaining the time from the network NTP server, but it is not drifting to adjust it forward:

< 1854.770> [Console] command: /usr/bin/ntpdate-sync
< 1854.770> [eConsoleAppContainer] Starting /bin/sh
< 1862.919> [Console] finished: /usr/bin/ntpdate-sync
< 1862.920> [NetworkTime] setting E2 time: 1533395566.92
[snip ...]

< 3662.921> [Console] command: /usr/bin/ntpdate-sync
< 3662.921> [eConsoleAppContainer] Starting /bin/sh
< 3671.057> [Console] finished: /usr/bin/ntpdate-sync
< 3671.058> [NetworkTime] setting E2 time: 1533397375.06

but Mut@nt's syslog reports:

Aug 4 18:24:40 mutant51 daemon.err ntpdate[3979]: no server suitable for synchronization found
Aug 4 18:25:16 mutant51 daemon.err ntpdate[4005]: no server suitable for synchronization found
Aug 4 18:26:53 mutant51 daemon.err ntpdate[4064]: no server suitable for synchronization found

despite the fact my router (10.10.10.1) reports synchronisation packets are received from and returned to the Mut@nt (10.10.10.9):

18:30:18: receive: at 5982693 10.10.10.1<-10.10.10.9 VRF: -DEFAULT- flags 1 restrict 000
18:30:18: MRU: interval 101 headway 8 limit 64
18:30:18: receive: at 5982693 10.10.10.1<-10.10.10.9 mode 3/client:AM_FXMIT len 48 org 0000000000.00000000 xmt 0xdf1060c0.2a4c5fc4 NOMAC
18:30:18: sendpkt(38, dst=10.10.10.9, src=10.10.10.1, ttl=0, len=48)
18:30:18: fast_xmit: at 5982693 10.10.10.1->10.10.10.9 mode 4 len 48
18:30:20: receive: at 5982695 10.10.10.1<-10.10.10.9 VRF: -DEFAULT- flags 1 restrict 000
18:30:20: MRU: interval 2 headway 12 limit 64
18:30:20: receive: at 5982695 10.10.10.1<-10.10.10.9 mode 3/client:AM_FXMIT len 48 org 0000000000.00000000 xmt 0xdf1060c2.2a4a9e7d NOMAC
18:30:20: sendpkt(38, dst=10.10.10.9, src=10.10.10.1, ttl=0, len=48)
18:30:20: fast_xmit: at 5982695 10.10.10.1->10.10.10.9 mode 4 len 48
18:30:22: receive: at 5982697 10.10.10.1<-10.10.10.9 VRF: -DEFAULT- flags 1 restrict 000
18:30:22: MRU: interval 2 headway 16 limit 64
18:30:22: receive: at 5982697 10.10.10.1<-10.10.10.9 mode 3/client:AM_FXMIT len 48 org 0000000000.00000000 xmt 0xdf1060c4.2a4a5f16 NOMAC
18:30:22: sendpkt(38, dst=10.10.10.9, src=10.10.10.1, ttl=0, len=48)
18:30:22: fast_xmit: at 5982697 10.10.10.1->10.10.10.9 mode 4 len 48
18:30:24: receive: at 5982699 10.10.10.1<-10.10.10.9 VRF: -DEFAULT- flags 1 restrict 000
18:30:24: MRU: interval 2 headway 20 limit 64
18:30:24: receive: at 5982699 10.10.10.1<-10.10.10.9 mode 3/client:AM_FXMIT len 48 org 0000000000.00000000 xmt 0xdf1060c6.2a4abffe NOMAC
18:30:24: sendpkt(38, dst=10.10.10.9, src=10.10.10.1, ttl=0, len=48)
18:30:24: fast_xmit: at 5982699 10.10.10.1->10.10.10.9 mode 4 len 48

Is this another bug, or is there something missing from my settings?

 

[ccs]

I'd use transponder time, that's all I've ever used with freeview, and I haven't seen any issues you are now describing.