Opened 5 years ago

Closed 4 years ago

Last modified 4 years ago

#12281 closed Bug Report - General (Fixed)

Scheduler confused by stopping a failing recording

Reported by: Roger Siddons <dizygotheca@…> Owned by: gigem
Priority: minor Milestone: 0.28
Component: MythTV - Recording Version: Master Head
Severity: medium Keywords:
Cc: Ticket locked: no

Description

When one of my tuners dies, a recording on that tuner is correctly marked as "Failing" and Myth continues to try to tune.

If I cancel the recording using "Stop Recording" then the Upcoming Recordings page then shows it as "Recording" (both colour/list status and text). No file is produced. The Watch Recordings page only shows the empty file from the first tuning attempt, ie. no further files are created.

Attachments (14)

scheduler_confusion.log (51.6 KB) - added by Roger Siddons <dizygotheca@…> 5 years ago.
Annotated backend debug log - Recording "ITV News" by a dud tuner
failed.log (84.4 KB) - added by Roger Siddons <dizygotheca@…> 5 years ago.
Tuner still going after recording stopped
mythbackend-delete-resched-failed.log (31.2 KB) - added by Tom Dexter <digitalaudiorock@…> 4 years ago.
Failed, deleted, restarted recording starting at 2015-10-08 21:00:00
mythbackend.20151106_phantom.log (221.9 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
Creating a phantom recording
mythbackend.20151105_stop_race.log (132.3 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
Guide message causes race condition
0001-TVRec-Set-hostname-of-guide-progs-for-STOP_RECORDING.patch (1007 bytes) - added by Roger Siddons <dizygotheca@…> 4 years ago.
mythbackend.20151105_eit_fail.log (152.6 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
0002-TVRec-Close-failing-recordings-so-they-are-not-react.patch (1.6 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
mythbackend.20151105_stop_restarted.log (160.9 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
0003-Scheduler-Allow-restarted-failing-recordings-to-be-s.patch (1.2 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
mythbackend.20151105_reschedule_failed.log (115.5 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
0004-Scheduler-Schedule-repeats-when-failing-recording-is.patch (979 bytes) - added by Roger Siddons <dizygotheca@…> 4 years ago.
mythbackend.20151106_good_rec_not_stop.log (180.4 KB) - added by Roger Siddons <dizygotheca@…> 4 years ago.
0005-Fix-repeated-stopping-of-restarted-recordings.patch (966 bytes) - added by Roger Siddons <dizygotheca@…> 4 years ago.

Download all attachments as: .zip

Change History (36)

Changed 5 years ago by Roger Siddons <dizygotheca@…>

Attachment: scheduler_confusion.log added

Annotated backend debug log - Recording "ITV News" by a dud tuner

comment:1 Changed 5 years ago by Roger Siddons <dizygotheca@…>

The log appears to indicate that the scheduler treats the UI 'stop action' as a 'failed to tune/retry' event. However the tuner has been released and no further events occur. The "recording" state persists indefinitely.

comment:2 Changed 5 years ago by Roger Siddons <dizygotheca@…>

Forgot to mention this log was produced for a "Record this showing" rule, which may explain why it is being immediately rescheduled.

comment:3 Changed 5 years ago by gigem

Component: MythTV - SchedulingMythTV - Recording
Owner: changed from gigem to jpoet
Status: newassigned

comment:4 Changed 5 years ago by jpoet

Status: assignedaccepted

Changed 5 years ago by Roger Siddons <dizygotheca@…>

Attachment: failed.log added

Tuner still going after recording stopped

comment:5 Changed 5 years ago by Roger Siddons <dizygotheca@…>

Behaviour is not consistent. On another failure, stopping the recording appeared to work correctly - UI showed it as failed. However I saw 'Recording failing' notifications (2) every few minutes until the scheduled end time. EIT scanner was also trying to use same tuner. Log seems to suggest the failing EIT scan is being interpreted as the recording failing.

comment:6 Changed 4 years ago by Tom Dexter <digitalaudiorock@…>

In version 0.27.4 I experienced similar odd behavior after deleting and attempting to restart a failed recording...things that never happened with previous versions as described here:

http://www.gossamer-threads.com/lists/mythtv/users/591158

It never actually started re-recording at all, but the schedule was stuck in a "recording" state even after the scheduled end time of the show. I'll attach part of the backend log file (though it's just a general verbosity log). The failed show was "The Blacklist" starting at 2015-10-08 21:00:00.

Changed 4 years ago by Tom Dexter <digitalaudiorock@…>

Failed, deleted, restarted recording starting at 2015-10-08 21:00:00

comment:7 Changed 4 years ago by Roger Siddons <dizygotheca@…>

These issues arise from a combination of bugs in the recorder & scheduler. It manifests differently depending on UI use, use of active EIT, type of recording rule and presence of repeats.

The following annotated log shows one method of producing a 'phantom recording' that isn't writing to disk and cannot be stopped.

Note that deleting the recording does not seem to be relevant; it's the stopping of it that's at fault.

Deleting the recording rule has no effect on current recordings, presumably by design.

I've identified 4 separate issues that cause this type of behaviour. Running all of the following 4 patches I see consistent/correct behaviour on a single backend with dual DVB-T tuner. Failures were simulated by removing the aerial.

I haven't tested slave backend/remote tuners, nor 0.27. Some patches should be backportable but 0.28 has a lot of changes in this area and I don't have a 0.27 build available.

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Creating a phantom recording

comment:8 Changed 4 years ago by Roger Siddons <dizygotheca@…>

Issue 1.

Stopping recordings from the Schedule Guide causes a race condition between recorder and scheduler. In the following log note the difference between stopping from Upcoming Recordings and stopping from the guide . Whilst not a problem here, I have seen cases where the recorder changes the recording status whilst the scheduler is in mid-run. Also the scheduler can restart a recording before the recorder has closed the existing one. The consequences are difficult to identify.

Programmes on the guide have no hostname initialised (no need) but MS::DoHandleStopRecording? uses the hostname to distinguish slave requests. Thus all Guide STOP_RECORDINGS are treated as slave requests meaning the recording status update & reschedule is invoked before the recorder is stopped, instead of afterwards.

The following patch initialises hostnames for guide programmes to correct the message handling.

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Guide message causes race condition

Changed 4 years ago by Roger Siddons <dizygotheca@…>

comment:9 Changed 4 years ago by Roger Siddons <dizygotheca@…>

Issue 2.

When failing recordings are stopped, the recorder doesn't clear curRecording, so the next EIT scan restarts the recording. See following log.

Tearing down the recorder seems the neatest way. Will the current recording status ever be Failed ? Note the kFlagRecorderRunning flag is always cleared by TeardownRecorder? (within the lock).

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Changed 4 years ago by Roger Siddons <dizygotheca@…>

comment:10 Changed 4 years ago by Roger Siddons <dizygotheca@…>

Issue 3.

Failing recordings can only be stopped once. If a restarted recording starts failing and the user stops it, the scheduler immediately starts it again. See following log.

The patch fixes this specific case although I'm not convinced this is the right way to determine 'user stopped so don't reactivate.'

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Changed 4 years ago by Roger Siddons <dizygotheca@…>

comment:11 Changed 4 years ago by Roger Siddons <dizygotheca@…>

Issue 4.

As soon as a recording starts failing, future repeats are scheduled to record. However, if the recording is stopped, the repeats get unscheduled (they are marked Previously Recorded). See following log. I suspect this also occurs if the failing recording finishes (without being stopped) but haven't tried it.

This patch leaves the repeats scheduled (but may have undesirable consequences for other statuses)

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Changed 4 years ago by Roger Siddons <dizygotheca@…>

comment:12 Changed 4 years ago by Roger Siddons <dizygotheca@…>

An additional bug is that (good) recordings cannot be stopped after being restarted twice - the UI stop request is simply ignored. This is a minor issue and does not put the recorder/scheduler into an errant state. It is caused by the mismatch between a restarted recording's starttime and the programme start time.

Changed 4 years ago by Roger Siddons <dizygotheca@…>

Changed 4 years ago by Roger Siddons <dizygotheca@…>

comment:13 Changed 4 years ago by Stuart Auchterlonie

Milestone: unknown0.28

comment:14 Changed 4 years ago by gigem

Owner: changed from jpoet to gigem
Status: acceptedassigned

Thanks for continuing to look into this Roger. Your fix for issue 1 is definitely an oversight. I'll defer to our recorder guy on issue 2. Your fix for issue 3 is definitely wrong. I'll look into the correct fix. I think issue 4 is the result of the bad fix for issue 3. I'll look into it and issue 5 after properly fixing issue 3.

comment:15 Changed 4 years ago by Roger Siddons <dizygotheca@…>

In 2c1e672be965551f2c1007b9725020b606cd0878/mythtv:

Copy hostname from scheduler too when creating a new ProgramInfo?.

The hostname is needed to be able to stop the recording in some cases.

Signed-off-by: David Engel <dengel@…>

Refs #12281

comment:16 Changed 4 years ago by Roger Siddons <dizygotheca@…>

In 36f15c8edd3d58a603375a383c6096b941b1fa82/mythtv:

Properly cleanup when stopping a failing recording.

Previously, the recorder was left in a bad state which caused restarts
to fail.

Signed-off-by: David Engel <dengel@…>

Refs #12281

comment:17 Changed 4 years ago by David Engel <dengel@…>

In cf528b39a8a926cc91bd951c887d15f724dcbeab/mythtv:

Clear reactivate when updating the history in oldrecorded.

Previously, the reactivation status was preserved and could cause
programs to keep getting restarted. Reactivate was always intended to
be a 'single shot', so make it that way.

Refs #12281

comment:18 Changed 4 years ago by David Engel <dengel@…>

In 9220e7945e9f7e35734e361ba94c83f4a3aace59/mythtv:

Revert "Move StartedRecording? call from TVRec::StartRecording?() to"

This reverts commit 891b431664ebdbceafe41d7bf21be0d541dfc6ad.

That commit broke the returning of the recordingid and actual start
time saved in the recorded table to the scheduler.

Refs #12281

comment:19 Changed 4 years ago by gigem

Resolution: Fixed
Status: assignedclosed

I believe all issues are now fixed. I'll backport the relevant changes to fixes/0.27 in a few days.

comment:20 Changed 4 years ago by Roger Siddons <dizygotheca@…>

In 999aa8f0af15a67432742074aabbb1a1c1ce2e2c/mythtv:

Copy hostname from scheduler too when creating a new ProgramInfo?.

The hostname is needed to be able to stop the recording in some cases.

Signed-off-by: David Engel <dengel@…>

Refs #12281

Backported from master to fixes/0.27.

comment:21 Changed 4 years ago by Roger Siddons <dizygotheca@…>

In 7225aa0bb2a5eff578cdc0659b4d48a3326c9039/mythtv:

Properly cleanup when stopping a failing recording.

Previously, the recorder was left in a bad state which caused restarts
to fail.

Signed-off-by: David Engel <dengel@…>

Refs #12281

Backported from master to fixes/0.27.

comment:22 Changed 4 years ago by David Engel <dengel@…>

In cb5fd77d0a60edb20b2c6521beef188231b8e8fc/mythtv:

Clear reactivate when updating the history in oldrecorded.

Previously, the reactivation status was preserved and could cause
programs to keep getting restarted. Reactivate was always intended to
be a 'single shot', so make it that way.

Refs #12281

Backported from master to fixes/0.27.

Note: See TracTickets for help on using tickets.