[VU+ Solo2] Exception No such file or directory: '/tmp/was_rectimer_wakeup'

[birdman]

I think I see the problem....well, at least the hint of a possible one.

When the AutoTimer code wants to add a new timer it calls:

recordHandler.record(newEntry)
​

where recordHandler is RecordTimer.
record() in RecordTimer.py calls addTimerEntry() (in timer.py), which calls calcNextActivation() (timer.py) which calls processActivation() (timer.py).
This is, in fact, precisely how the Traceback in the original log goes, but I've only just seen the significance (which I worked out by walking through the code - I've only just noticed that this agrees with the traceback...)

The comment in processActivation() says:

# we keep on processing the first entry until it goes into the future.
​

and that's the problem.
It does this by running the first timer on the list (they're sorted by next activation time) until the time of the first one is in the future.
BUT, if the first timer has just been fired off in another thread it may well not have yet had time to update its next activation time, so the AutoTimer thread fires it off for a second time - which is what we see. This will be a relatively rare event, which is why we haven't seen it many times.


My first suspicion is that the AutoTimer code (thread) shouldn't be trying to run processActivation() at all! In fact no sub-/background-processes should...

 

[ccs]

… autotimer had just found a new entry in the last log @< 228.689>, I'd chopped out all the garbage in the file beforehand.

 

[birdman]

From another thread....

And, in the good tradition of not rushing into fixes, I'm on to version 3.

The standard timers (handled by doActivate in timer.py) remove themselves from the timer_list as the first line of code in doActivate. So they won't be called again if we switch to another thread.

However, RecordTimers have their own doActivate and this doesn't remove them until after the internal activate is called. And that activate can feature file-system access, which is what triggers python to switch to the next thread that wants to run (specifically, it can check for /tmp/was_rectimer_wakeup).
So if I just move the code to remove the timer from timer_list to be at the start of activate all may be OK (provided no activate code expects to find the current timer on the timer list)

And now V4 as on checking through activate() in RecordTimer.py there are actually several bits of code that assume the current timer is still in the list (getNextZapTime() and, probably, saveTimer() for a start). So I can't just remove the timer from the list at the beginning of the code.
However, all we're trying to do is to stop the same timer being run twice (as a result of swapping the running thread) in the loop in processActivation(). So all we need to do is to mark each timer as it is run (and unmark it afterwards) and not run it if it is marked.

So the loop becomes:

    # we keep on processing the first entry until it goes into the future.
    while True:
            timer_list = [ tmr for tmr in self.timer_list if (not tmr.disabled and not getattr(tmr, "currentlyActivated", False)) ]
            if timer_list and timer_list[0].getNextActivation() < t:
                    timer_list[0].currentlyActivated = True
                    self.doActivate(timer_list[0])
                    del timer_list[0].currentlyActivated
            else:
                    break

which will always stop it running any timer twice.

I'm running with this at the moment to check there are no oddities.

I can't check it against the original problem, as it's not easy (almost impossible) to set-up the required conditions. But the logic is (now) correct.

 

[birdman]

PR submitted:

https://github.com/OpenViX/enigma2/pull/420

 

[ccs]

Could this explain why, on vary rare occasions, my box wakes up from deep standby for a timer recording, but doesn't drop back to standby, because /tmp/was_rectimer_wakeup has gone missing?

 

[birdman]

Could this explain why, on vary rare occasions, my box wakes up from deep standby for a timer recording, but doesn't drop back to standby, because /tmp/was_rectimer_wakeup has gone missing?

No.
wasRecTimerWakeup, which is the internal flag set from that file's contents (starts as False), must end up set before the file is deleted. That's true even if two process attempt to do this (this bug); the first will set it, the second will crash but leave the variable unchanged.

 

[ccs]

Oldish thread, but another crash.....

 

[ccs]

Only possible clues are that 2 recordings (different mux's) both started at 12:58 from deep standby. 5 hours earlier than my normal routine, when just 1 timer usually starts from deep standby.

 

[birdman]

Only possible clues are that 2 recordings (different mux's) both started at 12:58 from deep standby.

That's what the previous fix was meant to handle. Clearly it doesn't.
I can look at it next week...

 

[birdman]

It's possible that the code I added created a copy of each of the timer entries, so would never se the other thread set the flag (as that would only happen in its copy).
I'll have to track down what python actually does for this code construct to confirm that....

EDIT: but this is not the case. The new list still refers to the original objects.

So I can't see why it doesn't work.
It would, however, be a simple task to add a lock around the was_rectimer_wakeup check. RecordTimer.py already has such code around writing a new timer entry (as setting a manual timer and AutoTimer setting a timer can occur simultaneously).

 

[birdman]

OK. I (have to) suppose that what is actually happening is that we have two different timers that pass through this code and so marking the first as activated still lets the second thread activate the second one.

So I'll add a lock around the file test....done. I'll let it run for a while before posting a PR.

 

[birdman]

https://github.com/OpenViX/enigma2/pull/576

 

[ccs]

.... thanks, I've installed it and setup tests for the next few days.