Record Timer List: Failed timers should not show `✅ Done`

[wedebe]

! Before you log an issue, have you updated to the most recent version? It's possible the issue may have already been fixed. 2023-04-30

Describe the bug / Actual behaviour: Timers which fail (eg. due to insufficient disk space) show ✅ Done

Expected behaviour: Timers which fail (eg. due to insufficient disk space) should show ❌ Failed

Has this issue started to happen just recently? I don't think this was always a bug, but can't recall when it last would have worked as expected.

To reproduce: Steps to reproduce the behaviour:

1. Set a record timer that will somehow fail
2. Open timer list and scroll to failed timer

Screenshots

Image/Box Model (please complete the following information): N/A

Additional context N/A

[jbleyel]

What's in the timers.xml for this failed timer?

[wedebe]

What's in the timers.xml for this failed timer?

Failed:

    <timer begin="1682903700" end="1682904600" marginBefore="0" eventBegin="1682903700" eventEnd="1682904600" marginAfter="0" hasEndTime="True" serviceref="1:0:1:C6C1:82A:2:11A0000:0:0:0:" eit="35106" cridSeries="[]" cridEpisode="crid://missing_authority/E6116382" cridRecommendation="[]" repeated="0" rename_repeat="1" name="NexTech" description="NexTech looks at tomorrow&apos;s industries, getting ahead of future trends and understanding the challenges that come with any new technological breakthroughs." location="/media/hdd/movie/" afterevent="auto" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0">
        <log code="0" time="1682897730">Timer created</log>
        <log code="0" time="1682903680">Mount &apos;/media/hdd/movie&apos; has insufficient free space to record.</log>
        <log code="12" time="1682903701">Stop recording.</log>
    </timer>

Successful:

    <timer begin="1683238200" end="1683238500" marginBefore="0" eventBegin="1683238200" eventEnd="1683238500" marginAfter="0" hasEndTime="True" serviceref="1:0:19:1B1C:802:2:11A0000:0:0:0:" eit="6608" repeated="0" rename_repeat="1" name="Weather" description="Weather bulletin. [S] [HD]" location="/media/sdb2/movie/" afterevent="auto" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0">
        <log code="0" time="1683237802">Timer created</log>
        <log code="11" time="1683238201">Start recording.</log>
        <log code="12" time="1683238500">Stop recording.</log>
    </timer>

[jbleyel]

Please try this:

https://github.com/openatv/enigma2/pull/2917

[wedebe]

Please try this:

2917

21:59:40.9288 [RecordTimer] Starting thread: 'writeable'.
21:59:40.9306 [RecordTimer] Finished thread: 'writeable'.
21:59:40.9307 [RecordTimer] Starting thread: 'freespace'.
21:59:40.9798 [RecordTimer] Finished thread: 'freespace'.
21:59:40.9802 [RecordTimer] Log: 'Okay, zapped away.'.
21:59:40.9807 Traceback (most recent call last):
21:59:40.9807   File "/usr/lib/enigma2/python/timer.py", line 47, in calcNextActivation
21:59:40.9815   File "/usr/lib/enigma2/python/timer.py", line 77, in processActivation
21:59:40.9818   File "/usr/lib/enigma2/python/RecordTimer.py", line 292, in doActivate
21:59:40.9828     if timer.activate():
21:59:40.9831        ^^^^^^^^^^^^^^^^
21:59:40.9832   File "/usr/lib/enigma2/python/RecordTimer.py", line 762, in activate
21:59:40.9844     self.failureCB(True)
21:59:40.9846   File "/usr/lib/enigma2/python/RecordTimer.py", line 1340, in failureCB
21:59:40.9864     InfoBar.instance.servicelist.performZap(self.service_ref.ref)
21:59:40.9868     ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
21:59:40.9875 AttributeError: 'ChannelSelection' object has no attribute 'performZap'
21:59:40.9877 [ePyObject] (PyObject_CallObject(<bound method Timer.calcNextActivation of <RecordTimer.RecordTimer object at 0xaf670bd0>>,()) failed)

[jbleyel]

You need to install the latest 7.3 image first. The image must be from 1.6. or later.

[wedebe]

You need to install the latest 7.3 image first. The image must be from 1.6. or later.

Running openATV 7.3.20230530 (2023-05-27) which is the latest available from http://images.mynonpublic.com/openatv/7.3/index.php?open=mutant51

[jbleyel]

Then you need to wait a few days and take the old RecordTimer.py from here to have a running box.

https://raw.githubusercontent.com/openatv/enigma2/7.2/lib/python/RecordTimer.py

[jbleyel]

You can now try the new RecordTimer.py again after update of your image.

[jbleyel]

Any news?

[jbleyel]

Hi @wedebe, have you tested the new RecordTimer.py?'

https://github.com/openatv/enigma2/pull/2917/commits/fc14ed2c85c2bb115ff204704800a016747b70e7

[wedebe]

Hi @wedebe, have you tested the new RecordTimer.py?'

fc14ed2

I won't be in a position to test this for a while as I don't have access to the box.

[jbleyel]

Hi @wedebe, have you tested the new RecordTimer.py?' fc14ed2

I won't be in a position to test this for a while as I don't have access to the box.

Can you estimate approximately when?

[wedebe]

Unfortunately @jbleyel ,this fix hasn't solved the problem.

[jbleyel]

Welcome back. What's the "state" attribute in timers.xml for this timer.

[wedebe]

Thanks Jörg,

There are actually 2 recording failures in the list, I only realised when I opened the xml.

    <timer begin="1691172000" end="1691179200" marginBefore="0" eventBegin="1691172000" eventEnd="1691179200" marginAfter="0" hasEndTime="True" serviceref="1:0:19:1B27:802:2:11A0000:0:0:0:" eit="10579" repeated="0" rename_repeat="1" name="Cycling: World Championships 2023" description="..." location="/media/hdd/movie/" afterevent="auto" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0">
        <log code="0" time="1691017306">Timer created</log>
        <log code="11" time="1691172000">Start recording.</log>
        <log code="16" time="1691176001">Write error while recording, mount &apos;/media/hdd/movie&apos; has not enough free space to record.</log>
        <log code="12" time="1691176100">Stop recording.</log>
    </timer>

    <timer begin="1691328600" end="1691330400" marginBefore="0" eventBegin="1691328600" eventEnd="1691330400" marginAfter="0" hasEndTime="True" serviceref="1:0:19:22D9:80D:2:11A0000:0:0:0:" eit="29427" repeated="0" rename_repeat="1" name="Click" description="..." location="/media/usb/movie/" afterevent="auto" disabled="0" justplay="0" always_zap="1" descramble="1" record_ecm="0" isAutoTimer="1">
        <log code="500" time="1691015717">[AutoTimer] Try to add new timer based on AutoTimer Click.</log>
        <log code="509" time="1691015717">[AutoTimer] Timer start on: Sun Aug  6 14:30:00 2023</log>
        <log code="0" time="1691328580">Mount &apos;/media/usb/movie&apos; has insufficient free space to record.</log>
        <log code="12" time="1691328600">Stop recording.</log>
    </timer>

[jbleyel]

This should be the finally fix.

https://github.com/openatv/enigma2/pull/2993/commits/aa31b3c421d23276e0ca49d4b3848566849b062f

[wedebe]

This should be the finally fix.

aa31b3c

This seems to have cleared/deleted all previously-existing timers.

With a test recording though, it now correctly shows a red icon, but still with the text Done, instead of Failed.

On reboot, once again the timers list is completely empty, but the test recording after the updated py files remains in the xml

Perhaps an additional line in the timer log file would be helpful: Timer failed to complete

[jbleyel]

Please provide a sample xml for the failed log entry.

[wedebe]

Observation dump:

init 4 rm /usr/lib/enigma2/python/RecordTimer.pyc cp RecordTimer.py /usr/lib/enigma2/python/ rm /usr/lib/enigma2/python/Screens/Timers.pyc cp Timers.py /usr/lib/enigma2/python/Screens/ init 6

/etc/enigma2/timers.xml remains with old entries (17.5KB)

open RecordTimers Overview zero entries shown exit overview /etc/enigma2/timers.xml is now empty of entries (43 bytes)

[wedebe]

Please provide a sample xml for the failed log entry.

With an empty timers.xml:

Set a record timer from Multi-channel EPG Notification appears - "Disk full?" open RecordTimers Overview One entry shown - ( ! ) Done timers1.xml.txt *NOTE: xml does not contain errored state

Full reboot timers2.xml.txt *NOTE: xml NOW contains errored state (ie. log isn't flushed at the right time)

open RecordTimers Overview zero entries shown

I don't see any reason for timers.xml data loss/corruption in /home/root/logs

Entries (including AuoTimer-created) only appear on screen in memory, not when loaded from /etc/enigma2/timers.xml

[jbleyel]

Is this empty list also happening if you have success timer in xml?

[wedebe]

Is this empty list also happening if you have success timer in xml?

Yes, all entries regardless of status are affected.

[wedebe]

It might be worth adding some exception logging while we're able to replicate the issue reliably

[jbleyel]

There is already a lot of debug log in RecordTimer.py.

https://github.com/openatv/enigma2/blob/master/lib/python/RecordTimer.py#L110-L128

[wedebe]

There is already a lot of debug log in RecordTimer.py.

https://github.com/openatv/enigma2/blob/master/lib/python/RecordTimer.py#L110-L128

I'm not seeing any of these entries in /home/root/logs or during init 5 :-/

[jbleyel]

Then you may need to add some extra prints. init 5 is wrong. The xml will be read on start and not on shutdown.

[wedebe]

Then you may need to add some extra prints. init 5 is wrong. The xml will be read on start and not on shutdown.

Is there a better way to capture logs in realtime than init 5?

[jbleyel]

Then you may need to add some extra prints. init 5 is wrong. The xml will be read on start and not on shutdown.

Is there a better way to capture logs in realtime than init 5?

init 4 to stop and then enigma2 to start .

[wedebe]

Then you may need to add some extra prints. init 5 is wrong. The xml will be read on start and not on shutdown.

Is there a better way to capture logs in realtime than init 5?

init 4 to stop and then enigma2 to start .

Thanks. What does init 5 achieve? It's mentioned in several forums.

[jbleyel]

Can you reproduce the issue with more logging?

Please don't edit the timers.xml by hand until enigma is running!

[wedebe]

Can you reproduce the issue with more logging?

Please don't edit the timers.xml by hand until enigma is running!

I've got a copy of timers.xml from before the new bug.

I haven't yet had time to add prints through the relevant files.

[jbleyel]

I have used your xml.

<?xml version="1.0" ?>

<timers>
        <timer begin="1691404500" end="1691404800" marginBefore="0" eventBegin="1691404500" eventEnd="1691404800" marginAfter="0" hasEndTime="True" serviceref="1:0:19:52D0:814:2:11A0000:0:0:0:" eit="39732" cridSeries="crid://missing_authority/C4210022010716211342" cridEpisode="crid://missing_authority/75143/152" cridRecommendation="[]" repeated="0" rename_repeat="1" name="Channel 4 News Summary" description="Channel 4&apos;s midday news summary.  [S]" location="/media/hdd/movie/" afterevent="auto" disabled="0" justplay="0" always_zap="0" descramble="1" record_ecm="0" failed="1">
                <log code="0" time="1691404446">Timer created</log>
                <log code="0" time="1691404480">Mount &apos;/media/hdd/movie&apos; has insufficient free space to record.</log>
                <log code="12" time="1691404500">Stop recording.</log>
        </timer>
</timers>

No issues here.

[wedebe]

timers1.xml.txt

Here's a file that fails for me on build 2023-08-10

[jbleyel]

No problem here.

[wedebe]

Have you rebooted?

Ohhhhh hang on... just spotted this:

21:41:05.3368 [PowerTimerEntry] DEBUG: Running init code.
21:41:05.3373 [PowerTimer] Timer 'PowerTimerEntry(type=autostandby, begin=Fri Aug 11 21:41:05 2023)'.

Deleting the power timer, rebooting and checking timers... they're all still there. Subsequently creating (any) power timer, rebooting, setting & letting a timer fail and checking timers... 💥 all gone!

[jbleyel]

Do you have crashlog or any error in debug log?

[jbleyel]

I need your debug log after creating the timer.

[wedebe]

I need your debug log after creating the timer.

This commit seems to be the culprit: https://github.com/openatv/enigma2/commit/37935e9ac4c09454b9c56629732e9ab2bab42095

Nothing obvious in the log:

00:19:40.9357 [RecordTimer] Starting thread: 'writeable'.
00:19:40.9376 [RecordTimer] Finished thread: 'writeable'.
00:19:40.9377 [RecordTimer] Starting thread: 'freespace'.
00:19:40.9863 [RecordTimer] Break: Error number 3.
00:19:40.9865 [RecordTimer] Log: 'Mount '/media/hdd/movie' has insufficient free space to record.'.
00:19:40.9887 [Skin] Processing screen 'MessageBox', position=(240, 160), size=(800x400) for module 'MessageBox'.
00:19:41.0043 [Screen] Warning: Skin is missing element 'QuestionPixmap' in <class 'Screens.MessageBox.MessageBox'>(Write error at start of recording. Disk full?
ITV News London).00:19:41.0044 
00:19:41.0046 [Screen] Warning: Skin is missing element 'InfoPixmap' in <class 'Screens.MessageBox.MessageBox'>(Write error at start of recording. Disk full?
ITV News London).00:19:41.0047 
00:19:41.0048 [Screen] Warning: Skin is missing element 'ErrorPixmap' in <class 'Screens.MessageBox.MessageBox'>(Write error at start of recording. Disk full?
ITV News London).00:19:41.0049 
00:19:41.0054 [MessageBox] Timeout set to 20 seconds.
00:19:41.0082 [Skin] Processing screen 'MessageBoxSummary' from list 'MessageBoxSummary, MessageBox_summary, ScreenSummary, SimpleSummary', position=(0, 0), size=(132x64) for module 'MessageBoxSummary'.
00:19:41.0097 [Screen] Showing screen '['MessageBoxSummary', 'MessageBox_summary', 'ScreenSummary', 'SimpleSummary']'.
00:19:41.0102 [Screen] Showing screen '['MessageBox']'.
00:20:01.0117 [RecordTimer] Log: 'Stop recording.'.
00:20:01.0396 [MessageBox] Timeout!

[jbleyel]

i cannot reproduce this. Can you please send me your PowerTimer xml and a short howto reproduce.

[jbleyel]

I have found your issue. All your timers are older than x days and will be removed after x days.

config.recording.keep_timers

[wedebe]

I have found your issue. All your timers are older than x days and will be removed after x days.

config.recording.keep_timers

So the bug is actually that the Recording Timer List is allowed to populate with expired entries when, in fact, they should first be discarded.

[jbleyel]

There is no bug. This is by design and i have no intention to add additional code and try to fix any unusual user changes.