DCR-2650 Recording Failure: Back-to-back, 2nd only recorded post-padding

[wtg]

Decided to use the DCR-2650 last night for our regular recording and doing so, I ran into issues.

I attempted to record the following shows:

Time Channel Name
20:00 - 21:00 906 Minute to Win It
20:30 - 21:00 908 The Middle
21:00 - 22:00 906 America's Got Talent
21:00 - 21:31 908 Modern Family
21:31 - 22:02 908 Modern Family

So, with two tuners, one would tune to 906 to record "Minute To Win It" followed by "America's Got Talent" and the other tuner would tune to 908 to record "The Middle" and both episodes of "Modern Family". It almost worked.

Everything seems to have recorded except for the last episode of Modern Family. While the log shows it started on time, all the file has is the last 2 minutes of post-padding First episode is 2+ GB, the second episode is 83MB. No errors in the log.

Code:

2011-08-31 19:59:00.238    [DEBUG][7]    allocating recording target filename: F:\video\recordings\Minute to Win It\Minute to Win It_20110831_20002100.ts
2011-08-31 19:59:00.238    [DEBUG][7]    About to start recording (9054): F:\video\recordings\Minute to Win It\Minute to Win It_20110831_20002100.ts
2011-08-31 19:59:00.410    [DEBUG][7]    SetTarget@2
2011-08-31 19:59:00.435    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner0/vchannel 906
2011-08-31 19:59:01.160    [DEBUG][7]    NIC: NVIDIA nForce Networking Controller
2011-08-31 19:59:01.162    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-08-31 19:59:01.193    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner0/target rtp://192.168.25.90:5000
2011-08-31 19:59:01.196    [DEBUG][7]    SetTarget@2
2011-08-31 19:59:01.198    [DEBUG][7]    Temp at 8/31/2011 7:59:11 PM
2011-08-31 19:59:01.198    [DEBUG][7]    Started recording (9054:F:\video\recordings\Minute to Win It\Minute to Win It_20110831_20002100.ts)
2011-08-31 19:59:01.351    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\video\recordings\Minute to Win It\Minute to Win It_20110831_20002100.ts" 906 9054
2011-08-31 20:29:00.297    [DEBUG][7]    allocating recording target filename: F:\video\recordings\The Middle\The Middle_20110831_20302100.ts
2011-08-31 20:29:00.298    [DEBUG][7]    About to start recording (9055): F:\video\recordings\The Middle\The Middle_20110831_20302100.ts
2011-08-31 20:29:00.338    [DEBUG][7]    SetTarget@2
2011-08-31 20:29:00.338    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/vchannel 908
2011-08-31 20:29:00.716    [DEBUG][7]    NIC: NVIDIA nForce Networking Controller
2011-08-31 20:29:00.717    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-08-31 20:29:00.725    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/target rtp://192.168.25.90:5001
2011-08-31 20:29:00.726    [DEBUG][7]    SetTarget@2
2011-08-31 20:29:00.728    [DEBUG][7]    Temp at 8/31/2011 8:29:10 PM
2011-08-31 20:29:00.728    [DEBUG][7]    Started recording (9055:F:\video\recordings\The Middle\The Middle_20110831_20302100.ts)
2011-08-31 20:29:00.802    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\video\recordings\The Middle\The Middle_20110831_20302100.ts" 908 9055
2011-08-31 20:59:00.229    [DEBUG][7]    Recording due to start pre-padding, but tuner not available

<snip - A bunch of these "tuner not available" messages>

2011-08-31 21:00:00.235    [DEBUG][7]    allocating recording target filename: F:\video\recordings\Americas Got Talent\Americas Got Talent_20110831_21002200.ts
2011-08-31 21:00:00.267    [DEBUG][7]    About to start recording (9051): F:\video\recordings\Americas Got Talent\Americas Got Talent_20110831_21002200.ts
2011-08-31 21:00:00.279    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:00.279    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner0/vchannel 906
2011-08-31 21:00:01.116    [DEBUG][7]    NIC: NVIDIA nForce Networking Controller
2011-08-31 21:00:01.117    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-08-31 21:00:01.165    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner0/target rtp://192.168.25.90:5002
2011-08-31 21:00:01.168    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:01.266    [DEBUG][7]    SetTarget
2011-08-31 21:00:01.267    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:01.312    [DEBUG][7]    SetTarget@exit
2011-08-31 21:00:01.317    [DEBUG][7]    Temp at 8/31/2011 9:00:11 PM
2011-08-31 21:00:01.317    [DEBUG][7]    Started recording (9051:F:\video\recordings\Americas Got Talent\Americas Got Talent_20110831_21002200.ts)
2011-08-31 21:00:02.901    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\video\recordings\Americas Got Talent\Americas Got Talent_20110831_21002200.ts" 906 9051
2011-08-31 21:00:02.942    [DEBUG][7]    allocating recording target filename: F:\video\recordings\Modern Family\Modern Family_20110831_21002131.ts
2011-08-31 21:00:02.942    [DEBUG][7]    About to start recording (9052): F:\video\recordings\Modern Family\Modern Family_20110831_21002131.ts
2011-08-31 21:00:02.942    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:02.944    [DEBUG][7]    Execut    ing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/vchannel 908
2011-08-31 21:00:03.049    [DEBUG][7]    NIC: NVIDIA nForce Networking Controller
2011-08-31 21:00:03.050    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-08-31 21:00:03.051    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/target rtp://192.168.25.90:5000
2011-08-31 21:00:03.052    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:03.053    [DEBUG][7]    SetTarget
2011-08-31 21:00:03.053    [DEBUG][7]    SetTarget@2
2011-08-31 21:00:03.084    [DEBUG][7]    SetTarget@exit
2011-08-31 21:00:03.085    [DEBUG][7]    Temp at 8/31/2011 9:00:13 PM
2011-08-31 21:00:03.085    [DEBUG][7]    Started recording (9052:F:\video\recordings\Modern Family\Modern Family_20110831_21002131.ts)
2011-08-31 21:00:03.369    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\video\recordings\Modern Family\Modern Family_20110831_21002131.ts" 908 9052
2011-08-31 21:02:00.081    [DEBUG][7]    Stopping recording (9054). Past end time of recording.
2011-08-31 21:02:01.392    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\video\recordings\Minute to Win It\Minute to Win It_20110831_20002100.ts" 906 9054
2011-08-31 21:02:01.395    [DEBUG][7]    Stopping recording (9055). Past end time of recording.
2011-08-31 21:02:01.728    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\video\recordings\The Middle\The Middle_20110831_20302100.ts" 908 9055

<snip - A bunch more of the "Recording due to start pre-padding, but tuner not available" messages>

2011-08-31 21:31:00.215    [DEBUG][7]    allocating recording target filename: F:\video\recordings\Modern Family\Modern Family_20110831_21312202.ts
2011-08-31 21:31:00.224    [DEBUG][7]    About to start recording (9053): F:\video\recordings\Modern Family\Modern Family_20110831_21312202.ts
2011-08-31 21:31:00.253    [DEBUG][7]    SetTarget@2
2011-08-31 21:31:00.276    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/vchannel 908
2011-08-31 21:31:01.339    [DEBUG][7]    NIC: NVIDIA nForce Networking Controller
2011-08-31 21:31:01.340    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-08-31 21:31:01.379    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100542 set /tuner1/target rtp://192.168.25.90:5001
2011-08-31 21:31:01.382    [DEBUG][7]    SetTarget@2
2011-08-31 21:31:01.382    [DEBUG][7]    SetTarget
2011-08-31 21:31:01.382    [DEBUG][7]    SetTarget@2
2011-08-31 21:31:01.836    [DEBUG][7]    SetTarget@exit
2011-08-31 21:31:01.982    [DEBUG][7]    Temp at 8/31/2011 9:31:11 PM
2011-08-31 21:31:01.982    [DEBUG][7]    Started recording (9053:F:\video\recordings\Modern Family\Modern Family_20110831_21312202.ts)
2011-08-31 21:31:02.721    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\video\recordings\Modern Family\Modern Family_20110831_21312202.ts" 908 9053
2011-08-31 21:33:00.208    [DEBUG][7]    Stopping recording (9052). Past end time of recording.
2011-08-31 21:33:00.324    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\video\recordings\Modern Family\Modern Family_20110831_21002131.ts" 908 9052
2011-08-31 22:02:00.042    [DEBUG][7]    Stopping recording (9051). Past end time of recording.
2011-08-31 22:02:00.096    [DEBUG][7]    Graph stopping...
2011-08-31 22:02:00.301    [DEBUG][7]    Graph stopped
2011-08-31 22:02:00.365    [DEBUG][7]    Removing filter  NPVR Writer
2011-08-31 22:02:00.365    [DEBUG][7]    Removing filter  NPVR Net Push Source
2011-08-31 22:02:02.138    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\video\recordings\Americas Got Talent\Americas Got Talent_20110831_21002200.ts" 906 9051
2011-08-31 22:04:00.122    [DEBUG][7]    Stopping recording (9053). Past end time of recording.
2011-08-31 22:04:00.122    [DEBUG][7]    Graph stopping...
2011-08-31 22:04:00.297    [DEBUG][7]    Graph stopped
2011-08-31 22:04:00.297    [DEBUG][7]    Removing filter  NPVR Writer
2011-08-31 22:04:00.297    [DEBUG][7]    Removing filter  NPVR Net Push Source
2011-08-31 22:04:00.544    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\video\recordings\Modern Family\Modern Family_20110831_21312202.ts" 908 9053

I can post the entire log if you'd prefer.

[BrettB]

In my testing yesterday, I had 1 set of back-to-back recordings on the same channel. In my case, the first recording didn't get it's post-padding and the second recording didn't get it's pre-padding. I'm presuming that the CableCard technology doesn't support multi-record for the same frequency channels. However, in this case both recordings where on the same virtual channel. So I was wondering if there is a way that sub can support getting the pre- and post-padding for back-to-back recordings on the same virtual channel. In scheduling recordings yesterday, I did have several back-to-back recordings on the same channels over the next few days. And having each recording file be "complete" and "independent" (vs having to watch the beginning of the next recording to get the end of the first show, etc.) would be preferred, if it is possible. Can the HDHomeRun and DCR-2650 have multiple targets for a given tuner? If so, it seems like this request might be fairly easily doable. If not, then I guess you'd have to do something like use a multicast address that you would set the the target to send to and then have the multiple recording threads listen on that multicast address. That seems a bit more complicated.

[sub]

In my testing yesterday, I had 1 set of back-to-back recordings on the same channel. In my case, the first recording didn't get it's post-padding and the second recording didn't get it's pre-padding.

In this case, with two tuner, and no other recordings about start (other than those two), or live tv sessions in progress, then it should have used one tuner for each of the recordings and both should have ended up with padding.

If you want to reproduce this scenario and post the nrecord.log, then I'll take a look.

I'm presuming that the CableCard technology doesn't support multi-record for the same frequency channels. However, in this case both recordings where on the same virtual channel. So I was wondering if there is a way that sub can support getting the pre- and post-padding for back-to-back recordings on the same virtual channel.

Correct, you cant do multi-record on these types of devices. While technically it might be possible to come up with something for padding with back-to-back-on-same-channel, its unlikely this will happen, since it would require quite a few changes to the rules with which tuners currently operate, would be difficult with the way the HDHR network interface works, and potentially changes to the scheduler to favor tuner selection to support this. ie, a large amount of work for a scenario for a very small number users with a very limited situation. I'm not saying definitely no, but not likely to happen any time soon.

[BrettB]

In this case, with two tuner, and no other recordings about start (other than those two), or live tv sessions in progress, then it should have used one tuner for each of the recordings and both should have ended up with padding.

If you want to reproduce this scenario and post the nrecord.log, then I'll take a look.

Maybe it SHOULD have, but it DIDN'T... :eek:

I've attached the nrecord.log file from that particular instance. At 19:59 it shows Burn Notice starting recording with it's pre-padding on tuner0. At 20:59 (after moving one of the other clear QAM recordings on non DCR-2650 tuners), it shows messages that there is pre-padding requested, but no tuner available. Than at 21:00, it takes over tuner0 for the Suits recording and starts it without its pre-padding. I also notice that it doesn't "stop" the Burn Notice recording until 21:02 at the end of its post-padding time. However, since the Suits recording took over the tuner at 21:00 and routed the output to its file, there was no more stream data written to the Burn Notice file between 21:00 and 21:02. And then the post-processing (comskip) didn't begin until 21:02 either. With only 2 minutes of post-padding, this situation isn't a super big deal, but if it was set to something large like 60 or 90 minutes, I would definitely NOT want it to wait that long when it wasn't going to honor the post-padding.

[sub]

Its too hard to see what happened with other clear qam recordings going on at the same time.

Can you reproduce the problem from an empty database with only the DCR tuners mapped to your channels? I dont what it trying to move a recording to one of your QAM tuners.

[BrettB]

Its too hard to see what happened with other clear qam recordings going on at the same time.

Can you reproduce the problem from an empty database with only the DCR tuners mapped to your channels? I dont what it trying to move a recording to one of your QAM tuners.

Would it be ok if I just made a copy of my database and disabled the QAM tuners? Then I wouldn't have to go through all of the setup of the DCR-2650 channels again.

[sub]

Could you instead make a backup of the database, go in the settings for the QAM capture sources and delete all the channels, then restart everything, then schedule the recordings.

[wtg]

sub, any thoughts on the problem in the OP? As you can see above, there were no errors in the log and the second "Modern Family" recording got created on time and writing continued until the end, but only video from the post-padding time ended up in the file.
[ATTACH=CONFIG]31536[/ATTACH]

[BrettB]

Could you instead make a backup of the database, go in the settings for the QAM capture sources and delete all the channels, then restart everything, then schedule the recordings.

OK, here's that log file. I scheduled 3 or 4 back-to-back recordings. And only the 1st got it's pre-padding. The rest just have the error about no alternate tuner available. Then at the end, I set a 2nd recording to show that the 2nd tuner was setup and working. And then I cancelled both of those recordings and restarted them in the opposite order to show that both channels where configured and working on both tuners.

[sub]

OK, here's that log file. I scheduled 3 or 4 back-to-back recordings. And only the 1st got it's pre-padding. The rest just have the error about no alternate tuner available. Then at the end, I set a 2nd recording to show that the 2nd tuner was setup and working. And then I cancelled both of those recordings and restarted them in the opposite order to show that both channels where configured and working on both tuners.

What times had you expected these recordings to start/stop? They've got particularly odd start times, which makes me wonder if they're really back-to-back recordings.

2011-09-02 18:57:46.845 [DEBUG][7] About to start recording (23341): D:\NPVR Recordings\Seinfeld\Seinfeld_20110902_18301900.ts
...
2011-09-02 19:00:00.079 [DEBUG][7] About to start recording (23339): D:\NPVR Recordings\Family Guy\Family Guy_20110902_19001930.ts
...
2011-09-02 19:30:00.302 [DEBUG][7] About to start recording (23340): D:\NPVR Recordings\Family Guy\Family Guy_20110902_19302000.ts
...
2011-09-02 19:38:21.051 [DEBUG][7] About to start recording (23342): D:\NPVR Recordings\NCIS\NCIS_20110902_19002000.ts
...

Having other recordings scheduled for overlapping start/stop times can cause it to not move recordings to give optimal padding, since the tuner that it might move to could be required at sometime during that period for some other recording.