2.14 Some recordings won't stop on HDHR

[BrettB]

I'm pretty sure that I'm going to have another "record forever" recording in 30 minutes...

Tonight, Chaos was set to record from 7:00pm to 8:00pm. It appears to have recorded OK except that it didn't get its 2 minutes of requested post-padding.

And at 8:00pm (7:59pm with pre-padding) Expedition Impossible was supposed to record on a different channel (on a different frequency). And then at 9:00pm, Rookie Blue is set to record on the same channel as Expedition Impossible.

Just before 8:00pm, I opened the Device Status window from the tray app. It showed that Chaos was recording on my first tuner (an AverMedia). Then at 8:00pm, it added Expedition Impossible as recording on the same first tuner. And at 8:02pm, Chaos went off that tuner leaving just Expedition Impossible.

I'm attaching the complete NRecord.log file. Here are a few excerpts and observations:

Code:

2011-07-09 20:00:00.097    [DEBUG][7]    Scheduled Recording about to start maybe a candidate for moving to another tuner (different locator than another recording on same device)
2011-07-09 20:00:00.097    [DEBUG][7]    Existing:
<physical_channel>75</physical_channel>
2011-07-09 20:00:00.097    [DEBUG][7]    Required:
<physical_channel>79</physical_channel>
2011-07-09 20:00:00.097    [DEBUG][7]    Found another available tuner for new recording
2011-07-09 20:00:00.207    [DEBUG][7]    Recording successfully moved.

1. It seems to me that the first line should have been at 19:59 not 20:00 so that the 1 minute of pre-padding requested could have been honored.
   
2. It says that the recording was "successfully moved.", but apparently it wasn't since it's actually reocrding on the 1st tuner.
   

Code:

2011-07-09 20:00:00.247    [DEBUG][7]    Frequency has changed, so stopping recording from previous frequency. (Handle 1)

Code:

2011-07-09 20:02:00.107    [DEBUG][7]    Stopping recording (21572). Past end time of recording.
2011-07-09 20:02:00.107    [INFO][7]    DigitalRecorder.StopStream() handle: 1
2011-07-09 20:02:00.317    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "E:\NPVR Recordings\Chaos\Chaos_20110709_19002000.ts" 4 21572

1. At 20:00:00.247, it stopped writing out to the Chaos .ts file because the tuner had changed to a new frequency. Hence, Chaos didn't get its post-padding.
   
2. At 20:02, it "finishes" the Chaos recording and launches the PostProcessing.bat process.
   

At 8:59pm, I'll monitor to see what it does with the Rookie Blue recording and to see if it stops the Expedition Impossible recording.

[BrettB]

At 8:59pm, I'll monitor to see what it does with the Rookie Blue recording and to see if it stops the Expedition Impossible recording.

Here's the log info:

Code:

2011-07-09 20:59:00.217    [DEBUG][7]    allocating recording target filename: E:\NPVR Recordings\Rookie Blue\Rookie Blue_20110709_21002200.ts
2011-07-09 20:59:00.217    [DEBUG][7]    About to start recording (21565): E:\NPVR Recordings\Rookie Blue\Rookie Blue_20110709_21002200.ts
2011-07-09 20:59:00.217    [INFO][7]    DigitalRecorder.StartStream(E:\NPVR Recordings\Rookie Blue\Rookie Blue_20110709_21002200.ts)
2011-07-09 20:59:00.237    [INFO][7]    DigitalRecorder.StartStream() allocated handle: 0x3
2011-07-09 20:59:00.237    [DEBUG][7]    Temp at 7/9/2011 8:59:10 PM
2011-07-09 20:59:00.237    [DEBUG][7]    Started recording (21565:E:\NPVR Recordings\Rookie Blue\Rookie Blue_20110709_21002200.ts)
2011-07-09 20:59:00.347    [DEBUG][7]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2011-07-09 21:02:00.047    [DEBUG][7]    Stopping recording (21589). Past end time of recording.
2011-07-09 21:02:00.047    [INFO][7]    DigitalRecorder.StopStream() handle: 2
2011-07-09 21:02:00.207    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "E:\NPVR Recordings\Expedition Impossible\Expedition Impossible_20110709_20002100.ts" 5 21589

So, Rookie Blue started on tuner 1 at 8:59 and got its pre-padding.

But although the log file says that the recording stopped for Expedition Impossible at 21:02, it really hasn't. The device status screen still shows it on tuner 1. And the .ts file is still growing.

It DID launch the PostProcessing.bat process, but comskip isn't completing because the file keeps growing.

[sub]

Give this patch a go. I've only lightly tested it, but hopefully it'll fix the issue.

[BrettB]

Give this patch a go. I've only lightly tested it, but hopefully it'll fix the issue.

My initial testing looks like this fixed the problem with recordings not stopping. And part of the problem with tuner allocation. I just went into the TV Guide and selected a few back-to-back shows to record from 4 different channels (I think 3 different physical channels).

The logfile does still show one recording could not be moved, even though with the 4 tuners, it should have been possible to always honor the padding requests.

Code:

2011-07-10 12:29:00.174    [DEBUG][7]    Recording due to start pre-padding, but tuner not available
2011-07-10 12:29:00.175    [DEBUG][7]    Scheduled Recording about to start maybe a candidate for moving to another tuner (different locator than another recording on same device)
2011-07-10 12:29:00.175    [DEBUG][7]    Existing:
<physical_channel>71</physical_channel>
2011-07-10 12:29:00.175    [DEBUG][7]    Required:
<physical_channel>11</physical_channel>
2011-07-10 12:29:00.175    [DEBUG][7]    Was allocated to capture source1523
2011-07-10 12:29:00.183    [DEBUG][7]    Checking if multi-record possible...
2011-07-10 12:29:00.185    [DEBUG][7]    Checking if multi-record possible...
2011-07-10 12:29:00.186    [DEBUG][7]    Recording not moved. No other available tuner could be found.

I'm attaching the full logfile if you want to look at any of the other parts. And I'll watch the actual, normal recordings to see how the padding and stopping goes.

[sub]

My initial testing looks like this fixed the problem with recordings not stopping.

Great.

The logfile does still show one recording could not be moved, even though with the 4 tuners, it should have been possible to always honor the padding requests.

That is going to happen from time to time (due to various factors like order, future events, etc), but it should be quite a bit better at it than before. I will try to improve things further when I get I'm working in those areas though. (its going to be one big messy hard to maintain bit of code if I try to cover all scenarios though)

[roy]

Just to note - 2.1.5 has fixed the problem of recordings not stopping for me, but I still see no improvement of tuner logic to honor padding.

[sub]

Just to note - 2.1.5 has fixed the problem of recordings not stopping for me, but I still see no improvement of tuner logic to honor padding.

It did here. In fact, it was a failed attempt to move to a different tuner that caused the recording not stopping. The fixed corrected that logic that was moving recordings.

If you schedule two recordings, on different frequencies, in a back-to-back type scenario, then post the logs after the recordings, I'll take a look if it honored the padding, or if not why not.

[roy]

I can gather logs tonight, but to clarify, this is with my analog tuners, not digital frequencies, or HDHR.

[roy]

this is with my analog tuners

After further review, it does look like the logic is working to honor padding now. Back to back recordings on different channels do use available alternate tuners to provide padding. Back to back recordings on the same channel use the same tuner, so no padding, but you really don't need it since it's the same channel, so I guess that is logical. Thanks!

[BrettB]

Back to back recordings on the same channel use the same tuner, so no padding, but you really don't need it since it's the same channel, so I guess that is logical. Thanks!

Roy, I think that if you look closely at those back to back recordings on the same channel using the same tuner, you will find that they DO BOTH get the padding. During the period of padding overlap, the .ts stream from the tuner is being fed into both recording files at the same time. At least, that's how it seems to be working for me. (And has worked with NPVR for quite a while... The problem with losing padding was when the channel changed.)