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

[BrettB]

I recorded several things this afternoon, and all seemed to go OK until the last one tonight. It was supposed to end at 10:00pm, but is still recording now at 10:30pm. Here is the section from the nrecord.log file:

Code:

2011-09-03 18:29:00.079    [DEBUG][7]    Recording due to start pre-padding, but tuner not available
2011-09-03 18:29:00.080    [DEBUG][7]    Scheduled Recording about to start maybe a candidate for moving to another tuner (different locator than another recording on same device)
2011-09-03 18:29:00.080    [DEBUG][7]    Existing:
<sid>825</sid><tsid>0</tsid><map>0</map><chan>0</chan><name>USA HD</name>
2011-09-03 18:29:00.080    [DEBUG][7]    Required:
<sid>825</sid><tsid>0</tsid><map>0</map><chan>0</chan><name>USA HD</name>
2011-09-03 18:29:00.080    [DEBUG][7]    Was allocated to capture source1532
2011-09-03 18:29:00.092    [DEBUG][7]    Found another available tuner for new recording. Now allocated to 1533
2011-09-03 18:29:00.284    [DEBUG][7]    Recording successfully moved.
2011-09-03 18:29:00.285    [DEBUG][7]    allocating recording target filename: D:\NPVR Recordings\Pirates of the Caribbean At Worlds End [2007]\Pirates of the Caribbean At Worlds End [2007]_20110903_18302200.ts
2011-09-03 18:29:00.325    [DEBUG][7]    About to start recording (23477): D:\NPVR Recordings\Pirates of the Caribbean At Worlds End [2007]\Pirates of the Caribbean At Worlds End [2007]_20110903_18302200.ts
2011-09-03 18:29:02.408    [DEBUG][7]    SetTarget@2
2011-09-03 18:29:02.408    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100465 set /tuner1/vchannel 825
2011-09-03 18:29:09.304    [DEBUG][7]    NIC: Realtek PCIe GBE Family Controller
2011-09-03 18:29:09.305    [DEBUG][7]    NIC: Hauppauge OpenCable Receiver (MOCUR-SD)
2011-09-03 18:29:09.306    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100465 set /tuner1/target rtp://192.168.140.210:5000
2011-09-03 18:29:09.734    [DEBUG][7]    SetTarget@2
2011-09-03 18:29:09.735    [DEBUG][7]    Temp at 9/3/2011 6:29:19 PM
2011-09-03 18:29:09.735    [DEBUG][7]    Started recording (23477:D:\NPVR Recordings\Pirates of the Caribbean At Worlds End [2007]\Pirates of the Caribbean At Worlds End [2007]_20110903_18302200.ts)
2011-09-03 18:29:10.219    [DEBUG][7]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2011-09-03 18:32:00.030    [DEBUG][7]    Stopping recording (23476). Past end time of recording.
2011-09-03 18:32:00.030    [DEBUG][7]    Graph stopping...
2011-09-03 18:32:00.157    [DEBUG][7]    Graph stopped
2011-09-03 18:32:00.157    [DEBUG][7]    Removing filter  NPVR Writer
2011-09-03 18:32:00.157    [DEBUG][7]    Removing filter  NPVR Net Push Source
2011-09-03 18:32:00.257    [DEBUG][7]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 20100465 set /tuner0/target none
2011-09-03 18:32:00.585    [DEBUG][7]    Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "D:\NPVR Recordings\Pirates of the Caribbean Dead Mans Chest [2006]\Pirates of the Caribbean Dead Mans Chest [2006]_20110903_15311830.ts" 825 23476
2011-09-03 22:02:00.079    [DEBUG][7]    Stopping recording (23477). Past end time of recording.
2011-09-03 22:02:00.079    [DEBUG][7]    Graph stopping...

The log does show that it it moved the recording from tuner0 to tuner1. However, upon further investigation, I just discovered that the .ts file is 0 bytes long. :eek: The DCR-2650 status indicates that it is tuned and streaming. At the moment, I've still got it "running as is" in case there is something else that I should try to do to gather more data about why NPVR didn't capture the stream or why the graph didn't stop (maybe due to the previous problem of not ever starting capture properly?).

[BrettB]

At the moment, I've still got it "running as is" in case there is something else that I should try to do to gather more data about why NPVR didn't capture the stream or why the graph didn't stop (maybe due to the previous problem of not ever starting capture properly?).

When I tried to start a new recording, it didn't start. So, I stopped the NPVR Recording Serivce (using the utility in the menu). But, when I tried to restart it (again, using the utility in the menu), the NPVR Recording Service (in Windows Services) is NOT showing as running, but I am getting a process running NextPVR.exe and a Nrecord.log file which begins:

Code:

[...startup]
2011-09-03 22:54:08.331    [DEBUG][4]    OnStart()
2011-09-03 22:54:08.344    [INFO][4]    Using local in-process recording service
2011-09-03 22:54:08.631    [DEBUG][4]    RecordingServiceProxy@exit
2011-09-03 22:54:08.743    [INFO][4]    RecordingService.Startup()
2011-09-03 22:54:08.743    [INFO][4]    Starting remoting service
2011-09-03 22:54:08.780    [DEBUG][8]    Requesting wake up for 'EPGWAKEUP' at 9/4/2011 3:00 AM
2011-09-03 22:54:08.788    [INFO][4]    Starting web server on: 8866
2011-09-03 22:54:08.788    [INFO][4]    Setting working directory to: C:\Program Files (x86)\NPVR\
2011-09-03 22:54:08.788    [INFO][4]    Web root: C:\Users\Public\NPVR\web
2011-09-03 22:54:08.883    [INFO][7]    RecordingService starting...
2011-09-03 22:54:08.883    [DEBUG][7]    Loading recording schedule
2011-09-03 22:54:08.897    [DEBUG][7]    Requesting wake up for 'RecordingOID23482' at 9/3/2011 9:57 PM
2011-09-03 22:54:08.897    [DEBUG][7]    Requesting wake up for 'RecordingOID23479' at 9/4/2011 1:32 AM
....

My config.xml includes:

Code:

<Recording>
    <AllowInProcessRecording>false</AllowInProcessRecording>
    <ForceRecordingServiceUse>true</ForceRecordingServiceUse>

So something is definitely messed up here. I reverted back to the previous NShared.dll patch. And then everything started up OK and is recording OK again.

[sub]

I wouldnt think that change I made to NShared would have accounted for any significance difference, but I've removed it again for the next release anyway.

[roy]

I'm guessing the light being left on is purely cosmetic, and wont have any effect on things working. You could try the attach though, which explicitly tells the device that it's no longer using it (even though the docs say closing the connection is enough).

My initial testing with live tv found that the light stayed on and was still streaming after stopping with nPVR. This patch seems to have fixed it for me, so that it stops streaming and the light goes off.

[wtg]

Can you post the text from error message, along with the npvr.log?

I'm not sure, but this might simply have been stupid user error. I'm unable to reproduce it except for one way - if I don't restart the recording service. Sorry but I think I was a doofus.

[BrettB]

I successfully recorded several things this afternoon, but this evening, the recording service crashed. I'm attaching the logs files plus the dump file from C:\temp\.

[BrettB]

I successfully recorded several things this afternoon, but this evening, the recording service crashed. I'm attaching the logs files plus the dump file from C:\temp\.

Oh, I forgot to mention, it looks like the problem actually occurred at 20:59 when it was going to start the recording of The Glades, which is when the crash.mdmp file was created. However, the NRecord.exe process kept running and continued recording the things that were recording at that time (Hell's Kitchen & The Closer). Those channels kept being recorded until just a few minutes ago when I discovered the problem. I went to my session on the server, and had an unusual message saying that a background job need to display a message. When I clicked OK (or show message or whatever), I got a pop-up saying that a process had died and created the dump file in C:\temp. After I closed that message display, the NRecord.exe process went away. I then used the program menu items to Stop and then Start the NPVR Recording Service.

[sub]

Unfortunately that crash dump doesnt show any conclusive cause. The debugger shows the crash occurring in some .NET runtime function, with no NPVR code in the particular stack trace.

[BrettB]

During the night I had more recording failures. This time, it started recording Falling Skies at 0:59 and recorded it for 1 minute. Then it says it's about to start recording The Glades at 1:00 (with 1 minute pre-padding for a 1:01 start time). This time, there wasn't a crash dump, but almost everything else seems the same: recording service didn't start recordings after that, the tray device status stopped updating, the NMT host process kept working fine, etc. However, there was one difference: the other recording file (Falling Skies) STOPPED GROWING instead of continuing until I stopped the recording service with the utility. The DCR-2650 status indicates that both tuners are idle and the log does not show a tuning request for The Glades at 1:00, jut the one for Falling Skies at 0:59.

[soccerdad]

Just a guess,

I would check your signal strengths or anything else that might momentarily keep the recording service from getting the stream. Network traffic? It seems that any loss in the stream will crash the recording service. At that point, you won't get any more recordings. sub is working on making this not happen.