Problem with back-to-back recordings with HDHR Prime tuner on different channels

[BrettB]

I just found a problem recording made with one of my HDHR Prime (cablecard) tuners a few weeks ago. The problem recording is Chicago Med.S02E10.Heart Matters.ts. As I was watching Chicago Med, I noticed that at the end of it, an episode of Nightwatch began playing. The odd thing is that Chicago Med is on channel 811 and Nightwatch is on channel 829.

I don't have the nrecord.log file from 23 days ago. But my recordings log file shows that HDHR Prime Tuner 1-1 was used for both this recording and Nightwatch immediately following it:

Code:

Thu 01/12/2017 19:59:02.09 Recording "E:\NPVR Recordings2\Chicago Med\Chicago Med.S02E10.Heart Matters.ts" from channel 811 on tuner "HDHR Prime Tuner 1-1"
Thu 01/12/2017 21:01:00.52 Recording "E:\NPVR Recordings2\Nightwatch\Nightwatch.S03E07.105 and Rising.ts" from channel 829 on tuner "HDHR Prime Tuner 1-1"

And my postprocessing.log file, shows that Chicago Med did appear to keep recording through the full 5 minute post-padding with the Postprocessing.bat being invoked at 21:05:

Code:

Postprocessing.bat invoked for recording "E:\NPVR Recordings2\Chicago Med\Chicago Med.S02E10.Heart Matters.ts" (OID 186591) from channel 811 at Thu 01/12/2017 21:05:00.27

So it seems that after NextPVR changed the channel the HDHR tuner was tuned to, it kept recording the new channel's stream during the post-padding time into the .ts file of the first show. And, I think that this situation may be causing even more problems for playback because channel 829 is broadcast in H.264 while channel 811 is broadcast in MPEG-2. So the Chicago Med .ts file starts out as MPEG-2 video but then ends with H.264 video.

I cut a 150MB chunk from the end of the Chicago Med recording which shows this channel change. You can access it here: https://bowmantech-my.sharepoint.com/per...Ug4JAQcIsg

[BrettB]

So it seems that after NextPVR changed the channel the HDHR tuner was tuned to, it kept recording the new channel's stream during the post-padding time into the .ts file of the first show.

Watching the Nightwatch recording, it appears to have started right at the beginning of the show. So it appears that its pre-padding was ignored. (As would be expected when there wasn't an available tuner during the pre-padding tuning time period.) And the problem was just that the Chicago Med recording didn't stop (early, without post-padding) when the tuner was allocated to the Nightwatch recording and before the channel was changed.

[johnsonx42]

Some of what you're seeing is "just how npvr does it", combined with a bug.

When npvr starts a recording, it completely disregards any other recording happening on the tuner - if the tuner is supposed to be available, npvr takes it and starts the recording. if the new channel happens to be on the same physical frequency as the old channel, any prior recording that was going to continue with padding does so as intended; if not, the data stream simply stops and (normally) the recording just ends. however this is a case where the right hand doesn't know what the left hand is doing; as far as NRecord is concerned, that prior recording is still going on even though the data stream stopped, and any actions for stopping the recording do not occur until the post-padding is completed, even if it's not actually happening (the second log line snip you posted)

(as a note, in any prior post where I've said that nextpvr generally makes zero effort to make post-padding happen, and that it happens practically by accident if at all, this is what I was referring to)

With most tuners, when the channel changes, the old data stream stops and the recording file is closed cleanly. However you've found a bug (which I've seen reported before, but with less clarity) where with the HDHR Prime the old data stream continues with data from the new channel, so the old recording just continues with the new data. I suspect this can possibly make the file unplayable across the stream switch as well, if the stream change is too drastic. I suspect this is a bug stemming from the addition of same-channel multi-record to the Prime; it didn't originally do that.

That all said, you have committed the age-old sin of not posting your logs. The three log lines you posted are vaguely interesting, but not the ones with the proof (and I already knew what those lines said anyway). Since you don't know which ones I want to see, and certainly not which ones sub wants to see, post them all!

[BrettB]

That all said, you have committed the age-old sin of not posting your logs. The three log lines you posted are vaguely interesting, but not the ones with the proof (and I already knew what those lines said anyway). Since you don't know which ones I want to see, and certainly not which ones sub wants to see, post them all!

Hey, Johnson. I'm sure you just missed the part of my post where I said "I don't have the nrecord.log file from 23 days ago." They roll-over much too quickly for that! :p

That being said, I don't have any problem posting a .zip of my logs directory. I just did that in another post where I reported having a problem playing this Chicago Med file. So, I'm re-uploading it here, too for completeness.

[BrettB]

When npvr starts a recording, it completely disregards any other recording happening on the tuner - if the tuner is supposed to be available, npvr takes it and starts the recording.

Unless this behavior has changed, I don't think that this description is quite right. At least in the past, the way that it worked was that at the pre-padding time for a recording NextPVR would try to start the recording on the scheduled tuner if it was available or was already tuned to the proper channel. If not, then it would look to see if the new recording could be moved to a different tuner which was available now (and through the recording's end time). If so, then it would move the recording to that tuner and begin the pre-padding. If it couldn't find an available tuner, it would keep periodically checking during the pre-padding time to see if a suitable tuner had been freed up. If so, again, it would move to that tuner and begin the (reduced) pre-padding. If it got to the scheduled start time for the recording and no suitable alternative tuner had been found, then it would "force end" the recording currently using the scheduled tuner (which should be in its post-padding time or else NextPVR wouldn't have scheduled this recording to use that tuner to begin with). That tuner would then be available for this recording to use (missing its pre-padding, of course).

However you've found a bug (which I've seen reported before, but with less clarity) where with the HDHR Prime the old data stream continues with data from the new channel, so the old recording just continues with the new data. I suspect this can possibly make the file unplayable across the stream switch as well, if the stream change is too drastic. I suspect this is a bug stemming from the addition of same-channel multi-record to the Prime; it didn't originally do that.

I fully agree. Hence the reason I was reporting it here as a bug.

[johnsonx42]

Unless this behavior has changed, I don't think that this description is quite right. At least in the past, the way that it worked was that at the pre-padding time for a recording NextPVR would try to start the recording on the scheduled tuner if it was available or was already tuned to the proper channel. If not, then it would look to see if the new recording could be moved to a different tuner which was available now (and through the recording's end time). If so, then it would move the recording to that tuner and begin the pre-padding. If it couldn't find an available tuner, it would keep periodically checking during the pre-padding time to see if a suitable tuner had been freed up. If so, again, it would move to that tuner and begin the (reduced) pre-padding. If it got to the scheduled start time for the recording and no suitable alternative tuner had been found, then it would "force end" the recording currently using the scheduled tuner (which should be in its post-padding time or else NextPVR wouldn't have scheduled this recording to use that tuner to begin with). That tuner would then be available for this recording to use (missing its pre-padding, of course).

you're talking about pre-padding. nextpvr goes to all reasonable effort to get pre-padding. post-padding however is literally an after-thought. trust me, if you have a recording from 9:00 to 10:00, with five minutes post padding, at 10:00 that tuner is considered available, and the next recording will start with absolutely no regard to the post-padding. the recording will still run until 10:05, but usually the recording file will have closed at 10:00 when the stream closed. the NRecord.log will ALWAYS appear to show that every recording gets post-padding, only the NDigitalHost (or equivalent for your tuner) will reveal when the data stream actually ended.

[BrettB]

Sub: When you're back and have a chance to look at this problem, I can get you access to my system and/or one of my HDHRs if you need it. Also, if you need more logging or testing, I can temporarily disable some tuners and try to force the situation to happen.

[BrettB]

Bump for sub...

[sub]

You might need to try reproducing it so we can see a set of logs.

ie, backup your database, then temporarily delete the channels from all the tuners but one (to force it to use the same tuner), then setup a back to back scenario with 811 and 829, so we can see why the recording wasn't closed out when it decided the tuner wasn't available for post padding.

[BrettB]

You might need to try reproducing it so we can see a set of logs.

ie, backup your database, then temporarily delete the channels from all the tuners but one (to force it to use the same tuner), then setup a back to back scenario with 811 and 829, so we can see why the recording wasn't closed out when it decided the tuner wasn't available for post padding.

OK, I just did a test to reproduce the problem and get logs. FYI to force the test, I just disabled all but 1 tuner rather than deleting channels from different tuners. After disabling all but 1 tuner, I stopped the recording service and then restarted it. Then I went in and set a NCIS: LA episode (which was almost over) to record and set a Modern Family (immediately following the NCIS: LA episode, but on another channel) to also record.

When I looked at the logs directory, I did notice that there was one ndigitalhost- logfile (ndigitalhost-1535.log) which had just been updated when I shutdown the recording service. Nothing was recording at the time. And that file corresponds to a 3rd HDHR (non-Prime model) which I have that is connected to an antenna for OTA channel overflow. It's probably not related. But I did find it odd that only one of the 2 tuners on that HDHR showed an updated log file. Maybe only 1 of them had ever been used by the recording service since it was last restarted.

Anyway, as expected, the NCIS: LA recording did continue through its post-padding 5 minutes and those 5 minutes contained the stream from the Modern Family channel.