Occasional HDHR Recordings Failing

[BrettB]

I had 5 recordings fail last night:
   
   

This situation (although usually only 2-3 recordings) occasionally happens to me, but it's been infrequent and I generally don't notice in time to grab logs. This time I did.

In the log .zip, I added a HDHR_Log_2025-12-05.txt file which is the System log from the HDHR Quattro. The tuner there shows errors like

Code:

20251205-04:35:01 Tuner: failed to tune 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:35:01 HTTP: rejecting request from 192.168.143.10 - tune failed

each time, so I believe that the root cause may be something in the HDHR. I was running a 2023 version of the firmware and there was a 2025 version available. I thought that I had updated to that 2025 version when this happened the las time, but apparently not. I have done that now, so maybe that will resolve the issue on the HDHR side. We'll see.

The problem doesn't appear to be tied to any specific HDHR tuner or channel. In the log, I am seeing all 4 tuners being used successfully. And on any given night when the problem occurs, it affects different channels, but the same channels will also sometime records successfully the same night.

One interesting thing is the on the NextPVR recording end, I get 2 different failure messages/reasons: "HDHR stream not available" and "Recording interrupted". I feel like every time that this has happened, I've gotten a combination of these 2 failure messages. I'm not sure what the difference is.

It does appear that when the failure occurs, NextPVR is attempting to tune the channel multiple times using different tuners:

Code:

20251205-04:34:00 Tuner: tuner0 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:00 Tuner: tuner0 streaming http to 192.168.143.10:54390
20251205-04:34:00 Tuner: tuner0 http stream ended (remote closed)
20251205-04:34:00 Tuner: tuner2 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:01 Tuner: tuner2 streaming http to 192.168.143.10:54391
20251205-04:34:01 Tuner: tuner2 http stream ended (remote closed)
20251205-04:34:01 Tuner: failed to tune 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:01 HTTP: rejecting request from 192.168.143.10 - tune failed
20251205-04:34:01 Tuner: tuner1 tuning 5.1 KSTPDT (8vsb:599MHz-3)
20251205-04:34:01 Tuner: tuner1 streaming http to 192.168.143.10:54393
20251205-04:35:00 Tuner: failed to tune 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:35:00 HTTP: rejecting request from 192.168.143.10 - tune failed
20251205-04:35:00 Tuner: tuner0 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:35:00 Tuner: tuner0 streaming http to 192.168.143.10:54428
20251205-04:35:00 Tuner: tuner0 http stream ended (remote closed)
20251205-04:35:01 Tuner: tuner2 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:35:01 Tuner: tuner2 streaming http to 192.168.143.10:54429
20251205-04:35:01 Tuner: tuner2 http stream ended (remote closed)
20251205-04:35:01 Tuner: failed to tune 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:35:01 HTTP: rejecting request from 192.168.143.10 - tune failed
20251205-05:42:00 Tuner: tuner1 http stream ended (remote closed)

Also, in this case

Code:

20251205-04:34:00 Tuner: tuner0 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:00 Tuner: tuner0 streaming http to 192.168.143.10:54390
20251205-04:34:00 Tuner: tuner0 http stream ended (remote closed)
20251205-04:34:00 Tuner: tuner2 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:01 Tuner: tuner2 streaming http to 192.168.143.10:54391
20251205-04:34:01 Tuner: tuner2 http stream ended (remote closed)
20251205-04:34:01 Tuner: failed to tune 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-04:34:01 HTTP: rejecting request from 192.168.143.10 - tune failed

It appears that at 04:34:00, NextPVR first attempts to tune 4.1 on tuner0, the HDHR doesn't give a "tune failed" error, but NextPVR immediately (also at 04:34:00) closes the connection ("20251205-04:34:00 Tuner: tuner0 http stream ended (remote closed)") and immediately attempts to tune 4.1 on tuner2 which also immediately closes that connection ("20251205-04:34:01 Tuner: tuner2 http stream ended (remote closed)"). Then it immediately attempts to tune the same 4.1 channel a 3rd time which results in the "tune failed" error from the HDHR at 04:34:01.

[mvallevand]

The reason for the multiple attempts is NextPVR is trying to create a file

The.Late.Show.With.Stephen.Colbert.S11E45.Jen.Psaki;."Weird.Al".Yankovic.ts

And double quotes aren't allowed in Windows and must be escaped in Linux.

For the 503 reject is your tuner3 working?

Martin

[BrettB]

The reason for the multiple attempts is NextPVR is trying to create a file

The.Late.Show.With.Stephen.Colbert.S11E45.Jen.Psaki;."Weird.Al".Yankovic.ts

And double quotes aren't allowed in Windows and must be escaped in Linux.

For the 503 reject is your tuner3 working?

OK. So the "HDHR stream not available" errors are due to bad filenames. The same thing happened with the "?" in

Code:

Creating writer: D:\NPVR Recordings\Hells Kitchen\Season 24\Hells.Kitchen.S24E10.Is.It.Steak?.ts

Now that you mention it, I do recall that being a problem with some "special" characters in recording file names in the past. I had forgotten about that.

And maybe when that happens and NextPVR attempts to tune the same channel on basically all of the available tuners at the same time, it is triggering some problem with the HDHR firmware.

I think that tuner 3 works OK normally. But let me try to specifically test it.

[BrettB]

For the 503 reject is your tuner3 working?

I just went in a disabled tuners 0-2 so that only tuner 3 was available. And I was able to do quick recordings on all 4 major networks (WCCO-DT, KARE-HD, FOX 9, KSTPDT). For WCCO and Fox, the signal quality dropped down from 100% a few times, but always remained green in the HDHR monitor.

Code:

HDHomeRun CONNECT QUATRO

System Log
19700101-00:00:07 System: reset reason = firmware upgrade
19700101-00:00:07 System: network link 100f
19700101-00:00:08 System: ip address obtained: 192.168.143.44/24
19700101-00:00:08 System: ip address obtained: [fe80::218:ddff:fe07:6bcc]/64
19700101-00:00:18 System: ip address obtained: [fd72:8e41:58ca:5643:218:ddff:fe07:6bcc]/64
20251205-13:28:26 System: time changed from Thu Jan  1 00:00:23 1970 to Fri Dec  5 13:28:26 2025
20251205-13:28:30 System: ip address obtained: 169.254.196.81/16
20251205-14:57:43 Tuner: tuner3 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-14:57:43 Tuner: tuner3 streaming http to 192.168.143.10:50533
20251205-14:58:55 Tuner: tuner3 http stream ended (remote closed)
20251205-15:00:00 Tuner: tuner3 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-15:00:00 Tuner: tuner3 streaming http to 192.168.143.10:50596
20251205-15:00:41 Tuner: tuner3 http stream ended (remote closed)
20251205-15:00:57 Tuner: tuner3 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-15:00:58 Tuner: tuner3 streaming http to 192.168.143.10:50628
20251205-15:01:59 Tuner: tuner3 http stream ended (remote closed)
20251205-15:02:03 Tuner: tuner3 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-15:02:03 Tuner: tuner3 streaming http to 192.168.143.10:50653
20251205-15:02:44 Tuner: tuner3 http stream ended (remote closed)
20251205-15:13:59 Tuner: tuner3 tuning 11.1 KARE-HD (8vsb:575MHz-3)
20251205-15:13:59 Tuner: tuner3 streaming http to 192.168.143.10:50977
20251205-15:15:07 Tuner: tuner3 http stream ended (remote closed)
20251205-15:15:14 Tuner: tuner3 tuning 4.1 WCCO-DT (8vsb:581MHz-1)
20251205-15:15:14 Tuner: tuner3 streaming http to 192.168.143.10:51014
20251205-15:15:52 Tuner: tuner3 http stream ended (remote closed)
20251205-15:16:03 Tuner: tuner3 tuning 9.1 FOX 9 (8vsb:563MHz-4)
20251205-15:16:04 Tuner: tuner3 streaming http to 192.168.143.10:51042
20251205-15:16:26 Tuner: tuner3 http stream ended (remote closed)
20251205-15:16:33 Tuner: tuner3 tuning 5.1 KSTPDT (8vsb:599MHz-3)
20251205-15:16:34 Tuner: tuner3 streaming http to 192.168.143.10:51054
20251205-15:17:23 Tuner: tuner3 http stream ended (remote closed)

[mvallevand]

I will ask on the Silicondust forum when I have a chance.

Martin

[BrettB]

Here's another "bug" in this situation...

For the 2 recordings that show as "Failed: Recording interrupted" (Ghosts & Celebrity Family Feud), there are actually recording files out on the disk. And the post-processing script even ran successfully because the comskip .edl files were generated. The recordings were just cut off 1 minute before their scheduled ending time for some reason...
       

However, since the database has these recordings flagged as "Failed", the only option the UI is giving me is to "Delete". It makes it look like there isn't any recording there at all, and it won't let me play what is there.

[mvallevand]

The stop seems to be from the EPG

2025-12-04 19:59:14.798 [DEBUG][8] Recording 215073 stopped
2025-12-04 19:59:14.810 [DEBUG][8] Recording 215057 stopped

How many tuners do you have? I see 3 other recordings overlapped at that time

Also do you have a pause or wait in your batch files?

2025-12-04 19:59:31.189 [DEBUG][59] > Waiting for 17 seconds, press a key to continue ...16151413121110 9 8 7 6 5 4 3 2 1 0

Martin

[BrettB]

The stop seems to be from the EPG

2025-12-04 19:59:14.798 [DEBUG][8] Recording 215073 stopped
2025-12-04 19:59:14.810 [DEBUG][8] Recording 215057 stopped

How many tuners do you have? I see 3 other recordings overlapped at that time

Also do you have a pause or wait in your batch files?

2025-12-04 19:59:31.189 [DEBUG][59] > Waiting for 17 seconds, press a key to continue ...16151413121110 9 8 7 6 5 4 3 2 1 0

Humm... There shouldn't be any EPG update going on. The system should only be using Schedules Direct. And it is set to run at 2:44am.
   

Currently the system just has the 4 HDHR Quattro tuners.

There is a initial "timeout" in my post-processing batch file in case 2 recording end at the same time (so that their comskips get offset) and then a second one in a loop if there is already a comskip image running to limit it only running 1 at a time. I haven't made any changes to that in months (years?), so I don't think that should be a problem.

[mvallevand]

I didn't mean an EPG update I figured you modified the end time since you had five shows to record on four tuners.

This

Code:

2025-12-04 19:35:03.143    [DEBUG][38]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<Status>
  <Device oid="21" identifier="HDHomeRun 1076BCCD-0">
    <Recording handle="15000C">D:\NPVR Recordings\Ghosts\Season 05\Ghosts.S05E07.The.Proposal.ts</Recording>
  </Device>
  <Device oid="22" identifier="HDHomeRun 1076BCCD-1">
  </Device>
  <Device oid="23" identifier="HDHomeRun 1076BCCD-2">
    <Recording handle="17000A">D:\NPVR Recordings\Celebrity Family Feud\Season 11\Celebrity.Family.Feud.S11E10.The.Housemaid.vs.The.Housewives.All-Stars.Holiday.Special.ts</Recording>
  </Device>
  <Device oid="24" identifier="HDHomeRun 1076BCCD-3">
  </Device>
</Status>
</rsp>

turned into this completely illogically and one should have been deferred to 8 pm.  The original plan for tuners got messed up by the filename error or the 503 so that might have confused things.

Code:

2025-12-04 19:59:14.483    [DEBUG][45]    <?xml version="1.0" encoding="utf-8" ?>
<rsp stat="ok">
<Status>
  <Device oid="21" identifier="HDHomeRun 1076BCCD-0">
    <Recording handle="15000D">D:\NPVR Recordings\The Great Christmas Light Fight\Season 13\The.Great.Christmas.Light.Fight.S13E01.The.Holiday.Express.ts</Recording>
  </Device>
  <Device oid="22" identifier="HDHomeRun 1076BCCD-1">
    <Recording handle="16000E">D:\NPVR Recordings\Matlock\Season 02\Matlock.S02E07.Prior.Bad.Acts.ts</Recording>
  </Device>
  <Device oid="23" identifier="HDHomeRun 1076BCCD-2">
    <Recording handle="17000F">D:\NPVR Recordings\Next Level Baker\Season 01\Next.Level.Baker.S01E01.Baking.Spirits.Bright.ts</Recording>
  </Device>
  <Device oid="24" identifier="HDHomeRun 1076BCCD-3">
  </Device>
</Status>
</rsp>