Power Timer not updated due to shut down during backoff

[Grumpy_Geoff]

Firmware is 20181104.

Boots around 16:17 for a recording timer set for 16:21. Note the next Power Timer to fire is @ 17:00

Code: Select all

{735}<    74.798> [PowerTimer] PowerTimerEntry(type=wakeuptostandby, begin=Sat Dec  1 17:00:00 2018)
{735}<    74.800> [PowerTimer] PowerTimerEntry(type=wakeuptostandby, begin=Sun Dec  2 05:00:00 2018)
{735}<    74.801> [PowerTimer] PowerTimerEntry(type=wakeuptostandby, begin=Sun Dec  2 09:00:00 2018)
{735}<    74.801> [PowerTimer] PowerTimerEntry(type=wakeuptostandby, begin=Sun Dec  2 13:00:00 2018)
{735}<    74.802> [Navigation] RECTIMER: wakeup to standby detected.
{735}<    74.804> [IceTV] 2018-12-01 16:18:25: IceTV started
{735}<    74.807> [ShootYourScreen] start....
...

Recording timer stops, trashes are cleaned, then box proceeds to shut down to deep standby, setting a wakeup time for 10 mins hence and flagging that the start is for a Power Timer that should be stale given its start had well and truely passed (and, not that you can see it, but also its end time of 17:17 too).

Code: Select all

{735}<  3949.831> [RecordTimer] activating state 3
{735}<  3949.831> [RecordTimer] stop recording from: Tuner B
{735}<  3949.831> [eDVBServiceRecord] stop recording!
...
{958}<  3950.173> [Trashcan] probing folders
...
{735}<  3950.249> [Task] job Components.Task.Job name=Cleaning Trashes #tasks=1 completed with [] in None
...
{735}<  3950.253> dvb time sync disabled... so set RTC now to current linux time! Sat 01 Dec 2018 17:23
{735}<  3950.254> set wakeup time to Sat 01 Dec 2018 17:33
{735}<  3950.262> PowerTimerWakeupAuto True
{735}<  3950.318> [AutoTimer] No changes in configuration, won't parse
{735}<  3950.331> [EPGRefresh] Stopping Timer
{735}<  3950.333> [eDVBDB] ---- saving lame channel db
... box shuts down

I think the reason/issue is the Power Timer doesn't get completed - it doesn't have the log code 15 'time changed, start prepare is now: {x}' entry because it's backing off due to a recording timer that's still running.
The recording timer ends and the box shuts down. In this particular case the Power Timer after event action is to shut down to deep standby, so the after event should be considered actioned and the Power Timer updated for its next start.
Bug? Yes?

Power Timer log entries -

Code: Select all

<log code="15" time="1543600444">time changed, start prepare is now: Sat Dec  1 16:59:40 2018</log>
<log code="5" time="1543654780">activating state 1</log>
<log code="6" time="1543654780">prepare ok, waiting for begin</log>
<log code="5" time="1543654800">activating state 2</log>
<log code="5" time="1543655820">activating state 3</log>
<log code="10" time="1543655820">backoff: retry in 5 minutes</log>
<log code="5" time="1543656120">activating state 3</log>
<log code="10" time="1543656120">backoff: retry in 10 minutes</log>
</timer>

Times translated -

Code: Select all

root@beyonwizu4:/etc/enigma2# date --date=@1543600444
Sat Dec  1 01:54:04 AWST 2018
root@beyonwizu4:/etc/enigma2# date --date=@1543654780
Sat Dec  1 16:59:40 AWST 2018
root@beyonwizu4:/etc/enigma2# date --date=@1543654800
Sat Dec  1 17:00:00 AWST 2018
root@beyonwizu4:/etc/enigma2# date --date=@1543655820
Sat Dec  1 17:17:00 AWST 2018
root@beyonwizu4:/etc/enigma2# date --date=@1543656120
Sat Dec  1 17:22:00 AWST 2018
root@beyonwizu4:/etc/enigma2#

[prl]

... flagging that the start is for a Power Timer that should be stale given its start had well and truely passed (and, not that you can see it, but also its end time of 17:17 too).

The problem is parallel to one I've already addressed in RecordTimer. Backoff modifies the start time in the timer, so as far as the code is concerned, the power timer isn't stale at all: it's marked to run in the future.

The shutdown code should possibly also be looking differently at the kind of PowerTimer when it looks for what the next timer to run is (when i constructs wakeList in mytest.py). It should be ignoring PowerTimers that shut down the box, since that's what it wants to do right now.

Currently getNextPowerManagerTime() ignores AUTOSTANDBY and AUTODEEPSTANDBY timers. It should probably also ignore DEEPSTANDBY timers.

It's a bit unclear what it should do with REBOOT and RESTART timers, but I don't think it should ignore them.

[prl]

The problem is parallel to one I've already addressed in RecordTimer. Backoff modifies the start time in the timer

Actually, the problem I addressed was that when repeating power timers back off, it permanently changes the start time for the timer (e.g. if a power timer backs off for an hour because of a recording, future runs of that power timer will run an hour later than the timer was originally set for). Bug #448: Power timer start time permanently changed by timer backoff.

The fix for that bug (commit 580cc39) has disappeared from the code at some point, possibly as a result of an upstream merge.

However, that fix wouldn't have prevented this current problem.

Oddly, though, no-one has complained that the power timer drift problem has returned since the fix was undone.

There is a timer drift problem similar to #448 in recording timers, but it only happens on the transition StatePrepared -> StateRunning. Backoff in recording timers almost always happens on the StateWaiting -> StatePrepared and that doesn't cause timer drift.

[Grumpy_Geoff]

Thanks.
Yes, of course, I now realise a backed-off timer is still in-progress.
Based on that point of yours, I thought about splitting the Power Timer's two 'wakeup to standby' and 'go to deep standby' actions out into separate timers. The former can't get backed off, and whilst the latter can still potentially be backed off, its reason d'etre is to shut down, not bring the box out of deep standby and thus possibly not be the target of an unwanted startup.
So I gave that a try, with a recording timer already in progress, the 'wakeup to standby' P/T was already satisfied, whilst the 'go to deep standby' started to backoff at its specified start time, and it appears it got dumped on when the recording timer shut the box down. I waited an hour and there was no subsequent startup, whereas with the in progress combo P/T it started up 10 minutes after shutdown (perhaps that was aligned to the 5, 10, 20, 30 mins backoff increments?).

I booted the box back up and observed the shut down P/T had its next start time correctly altered once the [PowerTimer] instance had loaded its contents from file.
Looking in the penultimate log I can see the next start time was set for a recording timer, as one would expect.

The takeaway for me is - don't be a smart arse and cut corners (meaning don't use one power timer for two purposes)

I haven't been using "timed" Power Timers until now, so I wouldn't have observed the clock drift. However, I didn't get the modified start time in the case noted in the opening post. Perhaps because it was a timed after event action and not a start action?

[prl]

I've revisited this to write up something for the issue tracker, but now I'm a bit puzzled. If the PowerTimer causing the problem is "wakeup" or "wakeup to standby" it should never be backed off unless it has a "go to deep standby" after event which will back off the after event but the main timer event won't be backed off..

Geoff, could you post a copy of the power timer?

[Grumpy_Geoff]

Sorry Peter, I don't have that Power Timer (or others) in that form any more. But yes, it had the after event action of 'go to deep standby', and that after event was being backed off, which then caused the subsequent P/T wakeup boot set for a time that is {x-backoff-period} minutes into the future. The boot is for a "non-existent" P/T as there is nothing to be processed.

Here's the pm_timers.xml log entries -

Code: Select all

<log code="15" time="1543600444">time changed, start prepare is now: Sat Dec  1 16:59:40 2018</log>
<log code="5" time="1543654780">activating state 1</log>
<log code="6" time="1543654780">prepare ok, waiting for begin</log>
<log code="5" time="1543654800">activating state 2</log>
<log code="5" time="1543655820">activating state 3</log>
<log code="10" time="1543655820">backoff: retry in 5 minutes</log>
<log code="5" time="1543656120">activating state 3</log>
<log code="10" time="1543656120">backoff: retry in 10 minutes</log>
<log code="15" time="1543656827">time changed, start prepare is now: Sun Dec  2 16:59:40 2018</log>

In there place I now have pairs of P/T timers - a 'wakeup to standby' P/T (no at end/after event), and its mate a 'go to standby' (note type) P/T with a start time of 15 mins later and an end time set for a further 2 mins hence with an after event action of 'go to deep standby'.
I was trying these pairs to see if there would still be an after-event backoff, which there is, so they're no better.
I also tried a 'wakeup to standby' and its pairing of a 'go to deep standby' P/T but eventually realised that a deep standby P/T type won't be actioned _if_ the box was brought out of deep standby by a P/T (i.e. 'POWERTIMER: wakeup {to standby} detected').

It should be easy to re-create the reported issue -

• recording timer for 17:30-18:00, with after event of 'go to deep standby'
• Power Timer:
  • type is one of 'wakeup to standby', 'wakeup', 'go to standby' (I don't think it matters)
  • start is 17:35
  • end is 17:40
  • after event action is 'go to deep standby'

Power Timer will start at 17:35, and the after event will back off at 17:40 for 5 mins, then again at 17:45 for 10 mins, then again at 17:55 for 20 mins.
The recording will finish at 18:00 and put the box to deep standby. The Power Timer wakeup will be set -
set wakeup time to {date} 18:20
PowerTimerWakeupAuto True

Box will boot at 18:20, and go to standby. (Well, at least I think so )

I note that the "original" P/T did actually get its next start time correctly updated -

Code: Select all

<log code="15" time="1543656827">time changed, start prepare is now: Sun Dec  2 16:59:40 2018</log>

... at the next UI startup:

Code: Select all

root@beyonwizu4:/etc/enigma2# date --date=@1543656827
Sat Dec  1 17:33:47 AWST 2018

I suspect I was looking at the pm_timers.xml file and the in-memory contents had yet to be written to flash.

[prl]

Sorry Peter, I don't have that Power Timer (or others) in that form any more.

No problem. I only remembered after I posted that you'd changed the way it was done.

It should be easy to re-create the reported issue -

• recording timer for 17:30-18:00, with after event of 'go to deep standby'
• Power Timer:
  • type is one of 'wakeup to standby', 'wakeup', 'go to standby' (I don't think it matters)
  • start is 17:35
  • end is 17:40
  • after event action is 'go to deep standby'

Power Timer will start at 17:35, and the after event will back off at 17:40 for 5 mins, then again at 17:45 for 10 mins, then again at 17:55 for 20 mins.
The recording will finish at 18:00 and put the box to deep standby. The Power Timer wakeup will be set -
set wakeup time to {date} 18:20
PowerTimerWakeupAuto True

Thanks. I'll need that to do the bug report. It looks harder to deal with than what I originally thought. There are also weirdnesses like the fact that when the after event is backed off, the start time is updated, and then the end time is set to the start time if the start time is greater than the end time, which in these circumstances it always will be!

[Grumpy_Geoff]

Yes, if you read between my "lemon juice" lines, my real whinge is that the box boots up "for no reason" due to the box previous shutting down whilst the last P/T after-event shut down action is currently being backed off.

[prl]

Now I'm even more confused. I guess I just need to experiment.

[prl]

I've been able to replicate the problem. Next to look at the logs and maybe add some more debugging.

[Grumpy_Geoff]

Good-o for dogs, thanks.

[prl]

No problem. I mostly just wanted to let you know that I hadn't forgotten it.

[prl]

OK, I think the solution to this is that in PowerTimer.getNextPowerManagerTime(), the times checked should be timer.origbegin and timer.origend, not timer.begin and timer.end, so perhaps something like this:

Code: Select all

--- a/PowerTimer.py
+++ b/PowerTimer.py
@@ -606,7 +606,10 @@ class PowerTimer(timer.Timer):
                now = time()
                for timer in self.timer_list:
                        if timer.timerType not in (TIMERTYPE.AUTOSTANDBY, TIMERTYPE.AUTODEEPSTANDBY):
+                               save_begin, save_end = timer.begin, timer.end
+                               timer.begin, timer.end = timer.origbegin, timer.origend
                                next_act = timer.getNextWakeup()
+                               timer.begin, timer.end = save_begin, save_end
                                if next_act < now:
                                        continue
                                return next_act

The rationale is that the power timer times used in the shutdown part of mytest.runScreenTest() should be the values that will be in the pm_timers.xml file when that is written out when PowerTimer.shutdown() is written out. They will be the values in timer.origbegin & timer.origend.

The code is a bit ugly, but the alternative would be to allow a parameter to PowerTimer.getNextWakeup() to switch to returning the "orig" values if required.

I'm happy to look at suggestions for other, cleaner, ways of achieving the same result.

[Grumpy_Geoff]

Thanks.
You don't need to worry about other, cleaner, ways of achieving the same result from me, as all I want for Christmas is that if the box is shut down whilst the Power Timer is still backing off, it won't then subsequently needlessly boot in the near future {after x-backoff-period minutes}.

[prl]

I have a predisposition for clean solutions, and it annoys me that I can't think of one for this. timer.origbegin/end is already a bit ugly.

[Grumpy_Geoff]

I have a predisposition for clean solutions, ...

Yes, I'm aware of that

... timer.origbegin/end is already a bit ugly.

...but already in use for the previous "backoff" fix, right?
Yes, I know you'll likely say that was ugly too.

[prl]

I thought I was already saying I thought it was ugly

[Grumpy_Geoff]

I thought I was already saying I thought it was ugly

Yep, so you were - a comprehension fail on my part.

[prl]

I had another look at the code, and I discovered that the PowerTimer code contained two independent fixes for Bug #448: Power timer start time permanently changed by timer backoff, one by me, and one cherry-picked from OpenViX. The fix cherry-picked from OpenViX is probably a bit cleaner that the way I did the fix, but it can't be adapted to fix this bug as easily as my fix.

But fortunately I think I've found a simple way of doing backoff without modifying the timer start and end times at all. It deletes code to improve code, so it should meet with Grumpy_Geoff's approval.

I think that it can also be applied to the one instance of the RecordTimer code that changes the timer start/end times. That code also has the issue of permanently changing the start/end times of repeating timers, but it probably hasn't been noticed because I think it can only be triggered if the number of available tuners is reduced between the timer was created and when the timer starts. That can happen if a USB tuner is removed or fails to be recognised properly at system startup, or if a tuner fails between the creation of the timer and the time it runs.

[dRdoS7]

Hi,

While looking at this, would it possible to have PowerTimers (Standby at least) operate correctly when a Menu/Guide/etc. is displayed on screen?

Thanks,

dRdoS7