[mythtv-users] Recording live tv works but scheduled recordings fail for one channel only

Sat Oct 6 09:19:46 UTC 2018

Hi All,
I have a weird MythTV problem; I can watch channel "50 WIN HD Newcastle",
it tunes perfectly, I can then hit the record button and it records whatever
programme happens to be "live". However, if I choose to record channel 
"50 WIN HD Newcastle" via the programme guide, it fails to get a lock and I
get an empty, failed recording.

I can't understand this because, presumably, it is consulting the same channel
data for both operations.

I guess it could be something weird in the database as it has been going strong
since 2003! All perfectly upgrading the database to my current 0.29.1-31-g563a4b8.

Here's what I see in the log when I unsuccessfully attempt to do a record via 
the programme guide:

    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 0 0 0 - HandleRescheduleRecordings
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2469 (HandleReschedule) Scheduled 36 items in 0.2 = 0.08 match + 0.05 check + 0.04 place
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:1090 (HandleStateChange) TVRec[3]: Changing from None to RecordingOnly
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:3665 (TuningFrequency) TVRec[3]: TuningFrequency
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2923 (HandleRecordingStatusChange) Tuning recording: "Ten Eyewitness News": channel 1050 on cardid [3], sourceid 1
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: C CoreContext programinfo.cpp:340 (ProgramInfo) ProgramInfo(): Failed to find recorded entry for 0.
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) TVRec[4]: ASK_RECORDING 4 0 0 0
    Oct  6 18:48:52 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) TVRec[5]: ASK_RECORDING 5 0 0 0
    Oct  6 18:48:54 spug mythbackend: mythbackend[27942]: E TVRecEvent tv_rec.cpp:3962 (TuningSignalCheck) TVRec[3]: TuningSignalCheck: Hit pre-fail timeout
    Oct  6 18:48:55 spug mythbackend: mythbackend[27942]: W TVRecEvent tv_rec.cpp:3993 (TuningSignalCheck) TVRec[3]: TuningSignalCheck: taking more than 3000 ms to get a lock. marking this recording as 'Failing'.
    Oct  6 18:48:55 spug mythbackend: mythbackend[27942]: W TVRecEvent tv_rec.cpp:3995 (TuningSignalCheck) TVRec[3]: See 'Tuning timeout' in mythtv-setup for this input
    Oct  6 18:48:55 spug mythbackend: mythbackend[27942]: I CoreContext scheduler.cpp:734 (UpdateRecStatus) Updating status for "Ten Eyewitness News" on cardid [3] (Tuning => Failing)
    Oct  6 18:48:55 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2356 (HandleReschedule) Reschedule requested for CHECK -14 2541 0 UpdateRecStatus2 | Ten Eyewitness News |  | Comprehensive coverage of local, national and overseas news. Includes sport and the latest weather. |
    Oct  6 18:48:55 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2469 (HandleReschedule) Scheduled 36 items in 0.0 = 0.00 match + 0.00 check + 0.04 place

The recording fails to get a lock after 3000ms, in contrast, here 
is what I see when I watch the same "live" channel then hit the "record" button:

  Start watching "live" via programme guide:
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: I ProcessRequest mainserver.cpp:1738 (HandleAnnounce) MainServer: MainServer::ANN Playback
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: I ProcessRequest mainserver.cpp:1743 (HandleAnnounce) MainServer: adding: spug(201f2d0) as a client (events: 0)
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:1090 (HandleStateChange) TVRec[3]: Changing from None to WatchingLiveTV
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:3665 (TuningFrequency) TVRec[3]: TuningFrequency
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: N CoreContext autoexpire.cpp:251 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
    Oct  6 18:52:46 spug mythbackend: mythbackend[27942]: N TVRecEvent recordinginfo.cpp:695 (ApplyRecordRecGroupChange) ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
    Oct  6 18:52:47 spug mythbackend: mythbackend[27942]: N CoreContext autoexpire.cpp:251 (CalcParams) AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 4 min
    Oct  6 18:52:47 spug mythbackend: mythbackend[27942]: N TVRecEvent recordinginfo.cpp:695 (ApplyRecordRecGroupChange) ApplyRecordRecGroupChange: LiveTV to LiveTV (2)
    Oct  6 18:52:47 spug mythbackend: mythbackend[27942]: I TVRecEvent tv_rec.cpp:4236 (TuningNewRecorder) TVRec[3]: TuningNewRecorder - CreateRecorder()
    Oct  6 18:52:47 spug mythbackend: mythbackend[27942]: E TVRecEvent recorders/recorderbase.cpp:232 (SetStrOption) RecBase[3](1232B09C-1): SetStrOption(...recordingtype): Option not in profile.

  Hit the "record" button:
    Oct  6 18:52:57 spug mythbackend: mythbackend[27942]: I ProcessRequest tv_rec.cpp:2837 (SetLiveRecording) TVRec[3]: SetLiveRecording(1)
    Oct  6 18:52:57 spug mythbackend: mythbackend[27942]: I ProcessRequest tv_rec.cpp:2855 (SetLiveRecording) TVRec[3]: SetLiveRecording() -- record
    Oct  6 18:52:57 spug mythbackend: mythbackend[27942]: I CoreContext scheduler.cpp:1894 (AddRecording) Scheduler: AddRecording() recid: 2541
    Oct  6 18:52:57 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2356 (HandleReschedule) Reschedule requested for MATCH 2541 0 0 - AddRecording Ten Eyewitness News
    Oct  6 18:52:57 spug mythbackend: mythbackend[27942]: I Scheduler scheduler.cpp:2469 (HandleReschedule) Scheduled 36 items in 0.0 = 0.01 match + 0.00 check + 0.04 place

A successful recording appears in my "Watch Recordings" screen. This behaviour 
happens for all channels which share the same broadcaster/multiplex:

   50 WIN HD Newcastle
   51 ONE Newcastle
   52 ELEVEN Newcastle
   53 Sky News on WIN
   55 GOLD

All the other broadcaster/multiplex channels work as expected.

I tried deleting all my channels and doing a complete rescan but I
still get the same behaviour on these 5 channels.

Any thoughts on how to work out what is going wrong or where
to start looking?

The tuner is a HDHomeRun.

Any help hugely appreciated.

Cheers,

Doug