Exception No such file or directory: '/tmp/was_rectimer_wakeup'

[ccs]

Yes....

<   228.648> [eDVBFrontend0] opening frontend
<   228.649> [eDVBFrontend1] opening frontend
<   228.652> [eDVBFrontend2] opening frontend
<   228.687> [TimerSanityCheck] conflict not found!
<   228.690> [RecordTimer] activating state 2
<   228.692> [RecordTimer] activating state 2
<   228.694> [eDVBServiceRecord] Recording to /media/hdd/movie/20190505 1228 - ITV4 - Live Cycling - Tour de___.ts...
<   228.696> [eDVBServiceRecord] start recording...
<   228.696> [eDVBServiceRecord] RECORD: have 1 video stream(s) (07d1), and 2 audio stream(s) (07d2, 07d3) (07ef), and the pcr pid is 07d1, and the text pid is ffffffff
<   228.697> [eDVBServiceRecord] ADD PID: 0000
<   228.697> [eDVBServiceRecord] ADD PID: 07d0

It was the Tour de Yorkshire, I set up an autotimer, forgot about "all days", so eventually deleted it and created the Sunday timer as a one off timer.
I also edited it to add an extra hour to the end time. No sign of 2 timers.

[ccs]

My crash log in #6 has 2 activating state 2's as well.

[birdman]

Weird....one thing that both logs in this thread (one crash - that happened so quickly most of the log is there, and one debug) is that the AutoTimer thread was running when the recording started up (indeed, in the debug log it was the AutoTimer thread that crashed).

So I'd suggest that I put a mutex on the check for this file so that only one thread can ever run it at any given time. I did this somewhere else in OpenVix a few months back, so I just need to find that code and clone it.

EDIT: And, possibly, work out/look at how the AutoTimer thread can run through the StateRunning section of RecordTimer.

[ccs]

I've got the autotimer startup delay set to 3 minutes, which corresponds roughly with what the logs are saying.

I'm not sure what the default is, but the idea is for autotimer to catch changes to schedules asap, assuming they've reached the epg.

It looks like timers, waking up from deep standby, start up the recording at around the same time, 3 minutes after booting up.

[birdman]

I've got the autotimer startup delay set to 3 minutes, which corresponds roughly with what the logs are saying.

That's not the issue. The problem is that something is causing the RecordTimer code to be running in two threads at the same time. This is a problem if both run the StateRunning section.
I can't see why the AutoTimer code should do that: however, since it doesn't seem to cause a problem apart from this then it's possible that it should be running it.
In which case there needs to be a mutex around the "check file exists and delete it if there" code.

[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).