Some Recordings Fail

[MoisiePants]

Hello:

I apologise in advance - this is all going to be a bit vague. But I hope with the guidance of some more knowledgeable folks, I'll be able to provide some more concrete information...

I have a problem with some programmes randomly not recording; possibly related, every so often I find that my tuners (one HDHomeRun Connect HDHR4-2DT, containing two tuners) seem to have become unavailable - as though they're not being released after Myth has been using them.

For example, I had a timer set to record 'The White Princess' last night - here's the mythbackend log for the period in question:

Code: Select all

2020-03-01 01:02:38.634785 I [1070/17411] Scheduler scheduler.cpp:2357 (HandleReschedule) - Reschedule requested for MATCH 0 1 0 2020-03-01T06:00:00Z EITScanner
2020-03-01 01:02:39.331262 I [1070/9731] TVRecEvent tv_rec.cpp:3665 (TuningFrequency) - TVRec[1]: TuningFrequency
2020-03-01 01:02:40.844429 I [1070/17411] Scheduler scheduler.cpp:2470 (HandleReschedule) - Scheduled 45 items in 1.9 = 1.83 match + 0.00 check + 0.10 place
2020-03-01 01:04:00.135028 I [1070/17411] Scheduler scheduler.cpp:2357 (HandleReschedule) - Reschedule requested for PLACE PrepareToRecord
2020-03-01 01:04:00.512840 I [1070/17411] Scheduler scheduler.cpp:2470 (HandleReschedule) - Scheduled 45 items in 0.1 = 0.00 match + 0.00 check + 0.10 place
2020-03-01 01:04:01.141146 I [1070/17411] Scheduler scheduler.cpp:2357 (HandleReschedule) - Reschedule requested for MATCH 0 1 0 2020-03-01T07:00:00Z EITScanner
2020-03-01 01:04:01.809515 I [1070/10243] TVRecEvent tv_rec.cpp:3665 (TuningFrequency) - TVRec[2]: TuningFrequency
2020-03-01 01:04:03.346942 I [1070/17411] Scheduler scheduler.cpp:2470 (HandleReschedule) - Scheduled 45 items in 1.9 = 1.83 match + 0.00 check + 0.10 place
2020-03-01 01:04:30.282271 I [1070/9731] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[1]: ASK_RECORDING 1 148 0 0
2020-03-01 01:04:30.561380 I [1070/9731] TVRecEvent tv_rec.cpp:3665 (TuningFrequency) - TVRec[1]: TuningFrequency
2020-03-01 01:04:30.561396 E [1070/9731] TVRecEvent tv_rec.cpp:3743 (TuningFrequency) - TVRec[1]: Failed to set channel to . Reverting to kState_None
2020-03-01 01:04:31.022802 I [1070/9731] TVRecEvent tv_rec.cpp:3665 (TuningFrequency) - TVRec[1]: TuningFrequency
2020-03-01 01:04:31.023283 E [1070/9731] TVRecEvent tv_rec.cpp:3743 (TuningFrequency) - TVRec[1]: Failed to set channel to . Reverting to kState_None
2020-03-01 01:04:31.064883 I [1070/10755] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[3]: ASK_RECORDING 3 148 0 0
2020-03-01 01:04:31.064883 I [1070/11011] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[4]: ASK_RECORDING 4 148 0 0
2020-03-01 01:04:31.064906 I [1070/16387] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[9]: ASK_RECORDING 9 148 0 0
2020-03-01 01:04:31.064921 I [1070/16131] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[8]: ASK_RECORDING 8 148 0 0
2020-03-01 01:04:31.064922 I [1070/11779] TVRecEvent tv_rec.cpp:1639 (HandlePendingRecordings) - TVRec[7]: ASK_RECORDING 7 148 0 0
2020-03-01 01:05:00.196611 I [1070/9731] TVRecEvent tv_rec.cpp:1090 (HandleStateChange) - TVRec[1]: Changing from None to RecordingOnly
2020-03-01 01:05:00.360926 I [1070/9731] TVRecEvent tv_rec.cpp:3665 (TuningFrequency) - TVRec[1]: TuningFrequency
2020-03-01 01:05:00.392860 I [1070/17411] Scheduler scheduler.cpp:2924 (HandleRecordingStatusChange) - Tuning recording: "White Princess":"In Bed with the Enemy": channel 1020 on cardid [1], sourceid 1
2020-03-01 01:05:00.489758 C [1070/775] CoreContext programinfo.cpp:340 (ProgramInfo) - ProgramInfo(): Failed to find recorded entry for 0.
2020-03-01 01:05:07.265020 E [1070/9731] TVRecEvent tv_rec.cpp:3962 (TuningSignalCheck) - TVRec[1]: TuningSignalCheck: Hit pre-fail timeout
2020-03-01 01:05:08.098437 I [1070/17411] Scheduler scheduler.cpp:2357 (HandleReschedule) - Reschedule requested for MATCH 0 0 0 2020-03-01T06:00:00Z EITScanner
2020-03-01 01:05:10.285620 I [1070/17411] Scheduler scheduler.cpp:2470 (HandleReschedule) - Scheduled 45 items in 1.9 = 1.81 match + 0.00 check + 0.10 place
2020-03-01 01:05:10.706670 W [1070/9731] TVRecEvent tv_rec.cpp:3993 (TuningSignalCheck) - TVRec[1]: TuningSignalCheck: taking more than 10000 ms to get a lock. marking this recording as 'Failing'.
2020-03-01 01:05:10.706689 W [1070/9731] TVRecEvent tv_rec.cpp:3995 (TuningSignalCheck) - TVRec[1]: See 'Tuning timeout' in mythtv-setup for this input
2020-03-01 01:05:10.707123 I [1070/775] CoreContext scheduler.cpp:735 (UpdateRecStatus) - Updating status for "White Princess":"In Bed with the Enemy" on cardid [1] (Tuning => Failing)
2020-03-01 01:05:10.707901 I [1070/17411] Scheduler scheduler.cpp:2357 (HandleReschedule) - Reschedule requested for CHECK -14 1917 0 UpdateRecStatus2 | White Princess | In Bed with the Enemy | Historical drama series adapted from Philippa Gregory's novel. Henry Tudor is set to ascend to the throne, which puts Elizabeth of York in grave danger. | bds.tv/e9mrrp
2020-03-01 01:05:11.087736 I [1070/17411] Scheduler scheduler.cpp:2470 (HandleReschedule) - Scheduled 45 items in 0.1 = 0.00 match + 0.00 check + 0.10 place
2020-03-01 01:05:15.018265 E [1070/17923] JobQueue programinfo.cpp:2608 (GetPlaybackURL) - ProgramInfo(1020_20200301010500.ts): GetPlaybackURL: '1020_20200301010500.ts' should be local, but it can not be found.
2020-03-01 01:05:15.019865 E [1070/17923] JobQueue programinfo.cpp:2608 (GetPlaybackURL) - ProgramInfo(1020_20200301010500.ts): GetPlaybackURL: '1020_20200301010500.ts' should be local, but it can not be found.

Looking at the HDHR system log for that period:

Code: Select all

20200301-00:50:55 Tuner: tuner1 rtp stream ended (stop request)
20200301-00:51:59 Tuner: tuner0 rtp stream ended (stop request)
20200301-00:51:59 Tuner: tuner0 streaming rtp to 192.168.101.5:50170
20200301-00:53:54 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-00:57:19 Tuner: tuner0 rtp stream ended (stop request)
20200301-00:57:22 Tuner: tuner0 streaming rtp to 192.168.101.5:50170
20200301-00:58:57 Tuner: tuner1 rtp stream ended (stop request)
20200301-00:58:58 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:02:40 Tuner: tuner0 rtp stream ended (stop request)
20200301-01:02:40 Tuner: tuner0 streaming rtp to 192.168.101.5:50170
20200301-01:04:02 Tuner: tuner1 rtp stream ended (stop request)
20200301-01:04:05 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:04:31 Tuner: tuner0 rtp stream ended (stop request)
20200301-01:09:07 Tuner: tuner1 rtp stream ended (stop request)
20200301-01:09:07 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:14:11 Tuner: tuner1 rtp stream ended (stop request)
20200301-01:17:25 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:22:35 Tuner: tuner1 rtp stream ended (stop request)
20200301-01:22:35 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:27:45 Tuner: tuner1 rtp stream ended (stop request)
20200301-01:27:47 Tuner: tuner1 streaming rtp to 192.168.101.5:56083
20200301-01:32:55 Tuner: tuner1 rtp stream ended (stop request)

The HDHR log is filled with these brief repeating streaming requests, seemingly coming from my Myth machine (which is on 192.168.101.5). No other devices on my network attach to the HDHR.

I'm running Myth 29.1-ish on Mac OS X.

Any thoughts on what this might be, or what I can log more deeply to find out what's going on?

Thanks!

[MoisiePants]

Hello again:

Unfortunately I had the same issue again on the same programme last night too...

Looking at the system status now, there's definitely something amiss with tuners being held onto - here's what MythWeb says:

https://pasteboard.co/IXhSa0b.png

But the HDHR Tuner Status says otherwise:

https://pasteboard.co/IXhSvfZ.png
https://pasteboard.co/IXhSS5dh.png

And the HDHR app says the channels are in use:

https://pasteboard.co/IXhTidA.png

Any thoughts?

[AnalogBill]

I had a similar problem, now resolved. Not sure what actually fixed it, but I see a couple of differences between your setup and mine. Your 1st screenshot shows 12 tuners...I would expect only 2 tuners. The 6th line of your backend log references an eitscanner. I have this turned off.
Try this: Stop your backend from a terminal...sudo systemctl stop mythtv-backend
Then enter setup from the terminal...sudo mythtv-setup.real
You should now see the backend setup screen. Go to 2. Capture cards. I would expect to see only 2 HDHomerun tuners listed. If your screen shows more, I would delete all on your host, and then setup a new capture card. Now to check the EIT scanner. Select your capture card, on the next screen (which should show 'HDHomeRun networked tuner') hit your right-arrow key to move to the next screen. Go to Recording Options and again hit the right-arrow key. Uncheck the box for "Use HD HomeRun for active EIT scan". Repeat this for every tuner setup on your Capture Card page.
Finally, exit out of setup...IMPORTANT PART NEXT: Ignore any pop-ups asking if your want to start the backend, or run mythfilldatabase. JUST CLICK "NO" to these. Start the backend from the terminal....sudo systemctl start mythtv-backend.
You could now run mythfilldatabase from the terminal, or wait for the next automatic run.
Since unchecking the EIT scan box on my tuners, and starting/stopping the backend using systemctl rather than the pop-ups, I have not had failed recordings, or the "all tuners are busy" message. But, I'm a rookie at this, so welcome correction from others.

[MoisiePants]

Hi:

Many thanks for chiming in - much appreciated.

Your 1st screenshot shows 12 tuners...I would expect only 2 tuners.

I only have 2 tuners defined - but set for a maximum of 6 recordings in the Input Connections section.

Uncheck the box for "Use HD HomeRun for active EIT scan".

Ah yes - now this is interesting... Stupid me, I hadn't read this properly and had assumed this setting just allowed EIT data to be read from this tuner when it's not being used, or when it's tuned into a programme by the scheduler. Re-reading the description, I see this appears to take over the tuner just for EIT scanning - and I had it enabled for both tuners. Idiot me...

So I've now disabled it on both tuners and restarted my backend - and I can now see my HDHR log is blissfully quiet! Time will tell, of course...

So thanks for (hopefully) pointing me in the right direction Bill!

[AnalogBill]

I'm interested to learn how many simultaneous recordings you can make. My tuners are set to max of 1 recording each, but I'm going to test changing that.

Update: Set max recordings to 3, scheduled 3 recordings at the same time on 3 different local channels and got a "conflict". Two is the limit on my setup apparently. I have a HDHR4-2US device.

[wesnewell]

Been a while since I tested it, but I recorded 5 at once using 1 tuner. 5 sub-channels. I've got 6 tuners and i now have mine set to 2 each. I've never recorded more than 6 at once though. So without changing the most I could record now is 12 at once. What the heck, I'll give it a go. Hmm.. don't know how, but it's now recording 14 shows at the same time. Now to delete them all.

[MoisiePants]

Hi:

<Grrr - just typed up a big post, and then the forum logged me out before posting it!>

Update: Set max recordings to 3, scheduled 3 recordings at the same time on 3 different local channels and got a "conflict". Two is the limit on my setup apparently. I have a HDHR4-2US device.

I don't know how things run for you, but here in the UK, digital terrestrial broadcasts happen over a few multiplexes of a number of channels each. The tuner then picks up a multiplex, and Myth can extract and record more than one channel from this multiplex - up to the limit set in Max Recordings.

So I've now disabled it on both tuners...

...And now I'm not getting updated guide data. Of course, I'm using EIT for guide data - so I guess I'm now in Passive EIT Scanning mode, where data only gets updated whilst a tuner is tuned in for live watching or recording.

Of course, I can re-enable Use HD HomeRun for active EIT scan - but from this thread, it looks like active scanning takes place every 90 seconds or so - so it's going to completely tie up 1 of my 2 tuners: viewtopic.php?f=36&t=2644&p=12998&hilit ... ule#p13014

I don't know how this interacts with Myth Setup > General > EIT Scanner Options > Backend idea before EIT crawl too... I've looked through the Wiki and forum, and can't find a complete explanation for it.

I'm going to give it a go - but if there's a wise person who can explain, I'd be very interested. Otherwise it seems strange that I need to completely tie up a tuner - I must be missing something!

[wesnewell]

With atsc, each real channel (frequency) can support a number of sub-channels. Not sure what the max is but I know we have a couple here that has 7 sub-channels each. Some have an HD channel with 2-3 SD channels as well.

[MoisiePants]

I'm going to give it a go

Ok - I've had Use HD HomeRun for active EIT scan enabled on one tuner for the last 14 hours, and I can see in the tuner logs that it's been doing stuff almost continually during that time.

So I tried recording one programme whilst watching another from a different multiplex - and it does seem to be working. I guess the active EIT scan gives way to the request for live TV - but I don't know why this wouldn't have worked when I had both tuners set to active EIT scan.

I'll keep monitoring it, and if I have future failed recordings, I'll look into this aspect again.