Timer in prepare state should prevent a shut down

[Grumpy_Geoff]

Perfect storm!
A power timer with end time set for 17:20 and after event of "go to deep standby" rolls back at 17:20, possibly due to an impending timer in next 15 mins.
A record timer prepares at 17:24:40.
At 17:25:00 the power timer fires to shut down for its after event action, just at the time the record timer should've started to record.
The record timer doesn't get to begin recording. The box stays in shutdown, set to boot for the next timer.

Code: Select all

{920}<  1452.439> [RecordTimer] Filename calculated as: '/media/hdd/movie/20210712 1725 - 7mateHD Perth - AFL'
{920}<  1452.729> [RecordTimer] prepare ok, waiting for begin
{920}<  1472.573> [InputHotplug] connectionLost? [Failure instance: Traceback (failure with no frames): <class 'twisted.internet.error.ConnectionLost'>: Connection to the other side was lost in a non-clean fashion: Connection lost.
{920}<  1472.577> dvb time sync disabled... so set RTC now to current linux time! Mon 12 Jul 2021 17:25
{920}<  1472.578> set wakeup time to Mon 12 Jul 2021 19:20

[prl]

I can simulate this simply by setting a recording timer and a shutdown timer for the same time.

When the recording timer triggers the prepare phase 20 seconds before the start of the recording, and then sets the next activation for the recording timer, the underlying timer for the recording will be for the same time as the underlying timer for the shutdown timer, but queued after the shutdown timer.

I'm still thinking about "what happens next".

[prl]

OK, got it. It's down to the perils of comparing floats to ints (and that doesn't only bite on equality comparisons!).

If a power timer and recording timer are set for the same time, and the power timer code runs before the recording timer code, then the power timer checks whether it should back off by calling recordingsActive(900) (15-minute margin):

Code: Select all

def recordingsActive(margin):
	recordTimer = NavigationInstance.instance.RecordTimer
	return (
		recordTimer.isRecording() or
		abs(recordTimer.getNextRecordingTime() - time()) <= margin or
		abs(recordTimer.getNextZapTime() - time()) <= margin
	)

Because the recording timer has not yet run, the recording will still be in StatePrepared, not in StateRunning, and if there are no other recordings running, then recordTimer.isRecording() returns False.

You'd expect that the margin test on recordTimer.getNextRecordingTime() would succeed, but if the recording that's about to start is the only one starting within the margin, then there's a problem here:

Code: Select all

	def getNextRecordingTimeOld(self):
		now = time()
		for timer in self.timer_list:
			next_act = timer.getNextActivation()
			if timer.justplay or next_act < now:
				continue
			return next_act
		return -1

	def getNextRecordingTime(self):
		nextrectime = self.getNextRecordingTimeOld()
		... irrelevant stuff ...
		return nextrectime

getNextActivation() will return the integer "current time" as the time for the next activation of the recording timer (it's about to start), however, now is in floating point time, and will be slightly later than the start time of the recording timer. The recording timer start time will be something like ...12340, and now will be something like ...1234.001, so next_act < now will fail, and getNextRecordingTime() will return -1. That corresponds to the time 1969-12-31T23:59, which is well outside the margin of 15 minutes, so the power timer code concludes that there's no recording interfering with its operation and starts the shutdown sequence.

The bug will only be triggered if the power timer activates at the same second as the recording timer is due to start recording, but runs before it: in my tests, because they have the same time, and in Grumpy_Geoff's case, because the power timer triggered 5 minutes before the recording timer and was deferred for 5 minutes (power timers defer for 5min, 10min, 20min, 40min ... 60min, and then stay at 60min deferrals) The problem could also be caused by a power timer triggering exactly 15min (5 + 10 min) before the recording timer starts. A power timer triggering before that time will correctly shut the PVR down, and allow the recording timer to restart it.

It should be fixable by doing now = int(time()) in getNextRecordingTimeOld(), since the operations should take much less than 1 second to complete. There still may be a potential race condition if some other thread (or Linux process) grabs all the CPUs for more than a second while that code is trying to run.

[Grumpy_Geoff]

Good-o for dogs.
Thanks for taking the effort.
It's likely only me that is/will be affected, given I have 4 shut down Power Timers a day (and even then only a very slight chance of a recording timer scheduled for that exact shutdown time).
But what's the use of a PVR if it doesn't wake up to record?

[prl]

There still may be a potential race condition if some other thread (or Linux process) grabs all the CPUs for more than a second while that code is trying to run.

Unfortunately, I've realised that even with the int(time()) fix above, this problem can still happen if the conditions in my earlier are all met, but there is another event in the same second timeslot as the power timer, but whose code runs before the power timer and which takes more than a second to run (like, for example, an AutoTimer update).

There's also a potential for the problem to occur if the power timer is set for a minute before the recording, and a preceding timer at the same time lasts more than 40 seconds, and so gives a false comparison with the time.

I think that the correct way to do the comparison is to:

1. Have recordTimer.isRecording() (or a new function in its place) return True if the recording is either in preparing or running state.
2. Do any calculations that are relative to when a timer is activated be done relative to when the timer was due to run, rather than to the current time.

I hate stuff like this.