Oh! /tmp/was_rectimer_wakeup went AWOL - crash whilst recording

[Grumpy_Geoff]

Box woke up from deep standby for a recording. Then bang!

Code: Select all

{947}<   230.219> [RecordTimer] activating state 2
{864}<   230.220> [RecordTimer] activating state 2
consoleFd 10
[MAIN] executing main
TuxTxt service started 245
TuxTxt running thread...(245)
TuxTxt stopped service 245
{864}<   230.220> Traceback (most recent call last):
{864}<   230.220>   File "/usr/lib/enigma2/python/timer.py", line 264, in calcNextActivation
{864}<   230.221>   File "/usr/lib/enigma2/python/timer.py", line 335, in processActivation
{864}<   230.221>   File "/usr/lib/enigma2/python/RecordTimer.py", line 1047, in doActivate
{864}<   230.221>   File "/usr/lib/enigma2/python/RecordTimer.py", line 578, in activate
{864}<   230.221> OSError: [Errno 2] No such file or directory: '/tmp/was_rectimer_wakeup'
{864}<   230.221> [ePyObject] (CallObject(<bound method RecordTimer.calcNextActivation of <RecordTimer.RecordTimer instance at 0xb0b4b1c0>>,()) failed)
{866}<   233.296> [gRC] main thread is non-idle! display spinner!

Earlier,

Code: Select all

{864}<    34.852> [Navigation] RECTIMER: wakeup to standby detected.

Noting the 2 x "activating state 2".
Has there been a race condition where the left-hand removed /tmp/was_rectimer_wakeup, whilst the right-hand was expecting it to still be there (so it could delete it)?

[peteru]

Yes, it looks like two threads (947 and 864) running the same code at the same time. There's only one place where /tmp/was_rectimer_wakeup is removed.

There isn't enough log included to determine what the two threads were or how they got there.

[Grumpy_Geoff]

The log entry immediately before that was from an AutoTimer run, altering a timer (but not the one that was started) -

Code: Select all

{947}<   230.219> [RecordTimer] record time changed, start prepare is now: Fri Jun 11 21:19:50 2021

Thread 864 was the main thread setting up the recording that the box woke up for.

[Grumpy_Geoff]

Yes, it looks like two threads (947 and 864) running the same code at the same time. There's only one place where /tmp/was_rectimer_wakeup is removed.

There isn't enough log included to determine what the two threads were or how they got there.

More of the log from a few seconds before the crash is shown below.
Threads 947 and 949 were from an AutoTimer run.
Then thread 947 calls RecordTimer to alter a timer (for a definition not [yet?] listed ["Hitler's Supercars"], but the prepare time matches the change for the timer as shown further below).

Did thread 947 lose the plot and steal (the timer) thread 864's data?

Code: Select all

{947}<   225.715> [eEPGCache] lookup events with 'Fargo' as title (ignore case)
{949}<   226.219> [eEPGCache] lookup events with 'Fawlty Towers' as title (case sensitive)
{947}<   226.722> [eEPGCache] lookup events with 'Footy Classified' in title (ignore case)
{949}<   227.230> [eEPGCache] lookup events with 'Footy SA/WA' in title (ignore case)
{947}<   227.733> [eEPGCache] lookup events with 'Footy WA' in title (ignore case)
{939}<   228.117> [eEPGCache] schedule finished(1623312544)
{939}<   228.117> [eEPGCache] next update in 5 min
{947}<   228.972> [eEPGCache] lookup events, title starting with 'Gogglebox' (ignore case)
{949}<   229.476> [eEPGCache] lookup events with 'Halifax: Retribution' as title (ignore case)
{947}<   230.219> [RecordTimer] record time changed, start prepare is now: Fri Jun 11 21:19:50 2021
{947}<   230.219> [RecordTimer] activating state 2
{864}<   230.220> [RecordTimer] activating state 2
consoleFd 10
[MAIN] executing main
TuxTxt service started 245
TuxTxt running thread...(245)
TuxTxt stopped service 245
{864}<   230.220> Traceback (most recent call last):
{864}<   230.220>   File "/usr/lib/enigma2/python/timer.py", line 264, in calcNextActivation
{864}<   230.221>   File "/usr/lib/enigma2/python/timer.py", line 335, in processActivation
{864}<   230.221>   File "/usr/lib/enigma2/python/RecordTimer.py", line 1047, in doActivate
{864}<   230.221>   File "/usr/lib/enigma2/python/RecordTimer.py", line 578, in activate
{864}<   230.221> OSError: [Errno 2] No such file or directory: '/tmp/was_rectimer_wakeup'
{864}<   230.221> [ePyObject] (CallObject(<bound method RecordTimer.calcNextActivation of <RecordTimer.RecordTimer instance at 0xb0b4b1c0>>,()) failed)
{866}<   233.296> [gRC] main thread is non-idle! display spinner!

The timer that was shown as being modified -

Code: Select all

<timer begin="1623417610" end="1623422665" serviceref="1:0:19:325:320:3202:EEEE0000:0:0:0:" repeated="0" rename_repeat="1" name="Hitler&apos;s Supercars" description="Hitler&apos;s Supercars interweaves the rise of the Third Reich with the racing exploits it funded, and what propaganda messages these racing cars where sending." afterevent="auto" eit="12063" tags="" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" isAutoTimer="1">
<log code="500" time="1622768650">[AutoTimer] Try to add new timer based on AutoTimer Hitler (desc).</log>
<log code="509" time="1622768650">[AutoTimer] Timer start on: Fri Jun 11 21:20:00 2021</log>
<log code="15" time="1623312547">record time changed, start prepare is now: Fri Jun 11 21:19:50 2021</log>
</timer>

Epoch date 1623312547 ==> Thu Jun 10 16:09:07 AWST 2021