NRecord.exe dying

BrettB · 2014-10-27, 12:12 AM

My NPVR server is usually quite reliable--and I record A LOT of shows. But now, 2 Sundays in a row I seem to have had the NRecord.exe service "die". The first time was last Sunday (so version 3.2.9) and I wasn't home and didn't discover the problem until the next day when I had several failed recordings. Since I didn't catch it in time, I didn't get logs, and I just ignored it as some sort of fluke.

But just now, the service died on me again. This time it's version 3.3.8 which I installed Friday night. Maybe the two occurrences aren't related. But if they are, then the problem is not something new in 3.3.8.

Since I don't have the logs from the last time, I'll just focus on this instance where the logs are attached. I had 2 recordings running for the same channel both being recorded by 2 different tuners in an HDHR Prime with CableCard. It was in the post-padding for the 1st show (NFL Football) and the normal time for the 2nd show (60 Minutes). I was using the NMT client and from the Recordings listing, cancelled the NFL Football recording and then deleted it. The delete request brought up the confirmation dialog and I clicked OK. But the dialog stayed on the screen for a long time. That's when I noticed that both (rather than just 1) of the tuner in-use lights on the HDHR Prime had gone out. And the desktop gadget on my laptop couldn't connect to the recording service any longer. The NRecord.log doesn't seem to show any error. And the NFL Football recording and folder seemed to get deleted OK. I restarted the recording service and it immediately began recording 60 Minutes again (to a new file).

BrettB · 2014-10-27, 12:16 AM

OK, more investigation, and I found these Event Log entries:

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name="ASP.NET 4.0.30319.0" /> 

  <EventID Qualifiers="49152">1325</EventID> 

  <Level>2</Level> 

  <Task>0</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-26T23:32:47.000000000Z" /> 

  <EventRecordID>52719</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>An unhandled exception occurred and the process was terminated. Application ID: NRecord.exe Process ID: 21064 Exception: System.Collections.Generic.KeyNotFoundException Message: The given key was not present in the dictionary. StackTrace: at System.Collections.Generic.Dictionary`2.get_Item(TKey key) at NShared.RecordingService.WorkerThread() at System.Threading.ThreadHelper.ThreadStart_Context(Object state) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading.ThreadHelper.ThreadStart()</Data> 

  </EventData>

  </Event>

and

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name=".NET Runtime" /> 

  <EventID Qualifiers="0">1026</EventID> 

  <Level>2</Level> 

  <Task>0</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-26T23:32:47.000000000Z" /> 

  <EventRecordID>52720</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>Application: NRecord.exe Framework Version: v4.0.30319 Description: The process was terminated due to an unhandled exception. Exception Info: System.Collections.Generic.KeyNotFoundException Stack: at System.Collections.Generic.Dictionary`2[[System.Int32, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089],[System.Int32, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]].get_Item(Int32) at NShared.RecordingService.WorkerThread() at System.Threading.ThreadHelper.ThreadStart_Context(System.Object) at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) at System.Threading.ThreadHelper.ThreadStart()</Data> 

  </EventData>

  </Event>

and

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name="Application Error" /> 

  <EventID Qualifiers="0">1000</EventID> 

  <Level>2</Level> 

  <Task>100</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-26T23:32:49.000000000Z" /> 

  <EventRecordID>52721</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>NRecord.exe</Data> 

  <Data>1.0.0.0</Data> 

  <Data>544a8ced</Data> 

  <Data>KERNELBASE.dll</Data> 

  <Data>6.1.7601.18409</Data> 

  <Data>53159a86</Data> 

  <Data>e0434352</Data> 

  <Data>0000c42d</Data> 

  <Data>5248</Data> 

  <Data>01cff009c014073b</Data> 

  <Data>C:\Program Files (x86)\NPVR\NRecord.exe</Data> 

  <Data>C:\Windows\syswow64\KERNELBASE.dll</Data> 

  <Data>656a0922-5d68-11e4-b3d6-000dfe7e008d</Data> 

  </EventData>

  </Event>

BrettB · 2014-10-27, 12:20 AM

And there are 3 from last Sunday as well:

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name="ASP.NET 4.0.30319.0" /> 

  <EventID Qualifiers="49152">1325</EventID> 

  <Level>2</Level> 

  <Task>0</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-20T00:59:00.000000000Z" /> 

  <EventRecordID>52405</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>An unhandled exception occurred and the process was terminated. Application ID: NRecord.exe Process ID: 1032 Exception: System.NullReferenceException Message: Object reference not set to an instance of an object. StackTrace: Server stack trace: at NShared.DigitalRecorder.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at NDigitalHost.RecorderRemote.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg) Exception rethrown at [0]: at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg) at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type) at NUtility.IRecorder.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at NShared.DigitalRecorder.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at NShared.RecordingService.WorkerThread() at System.Threading.ThreadHelper.ThreadStart_Context(Object state) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) at System.Threading.ThreadHelper.ThreadStart()</Data> 

  </EventData>

  </Event>

and

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name=".NET Runtime" /> 

  <EventID Qualifiers="0">1026</EventID> 

  <Level>2</Level> 

  <Task>0</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-20T00:59:00.000000000Z" /> 

  <EventRecordID>52406</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>Application: NRecord.exe Framework Version: v4.0.30319 Description: The process was terminated due to an unhandled exception. Exception Info: System.NullReferenceException Stack: Server stack trace: at NShared.DigitalRecorder.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at NDigitalHost.RecorderRemote.IsLiveTVPossibleNow(Channel channel, Int32 ignoreHandle) at System.Runtime.Remoting.Messaging.StackBuilderSink._PrivateProcessMessage(IntPtr md, Object[] args, Object server, Object[]& outArgs) at System.Runtime.Remoting.Messaging.StackBuilderSink.SyncProcessMessage(IMessage msg) at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(System.Runtime.Remoting.Messaging.IMessage, System.Runtime.Remoting.Messaging.IMessage) at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(System.Runtime.Remoting.Proxies.MessageData ByRef, Int32) at NUtility.IRecorder.IsLiveTVPossibleNow(NUtility.Channel, Int32) at NShared.DigitalRecorder.IsLiveTVPossibleNow(NUtility.Channel, Int32) at NShared.RecordingService.WorkerThread() at System.Threading.ThreadHelper.ThreadStart_Context(System.Object) at System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) at System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) at System.Threading.ThreadHelper.ThreadStart()</Data> 

  </EventData>

  </Event>

and

Code:
- <Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">

- <System>

  <Provider Name="Application Error" /> 

  <EventID Qualifiers="0">1000</EventID> 

  <Level>2</Level> 

  <Task>100</Task> 

  <Keywords>0x80000000000000</Keywords> 

  <TimeCreated SystemTime="2014-10-20T00:59:01.000000000Z" /> 

  <EventRecordID>52407</EventRecordID> 

  <Channel>Application</Channel> 

  <Computer>Dogbert</Computer> 

  <Security /> 

  </System>

- <EventData>

  <Data>NRecord.exe</Data> 

  <Data>1.0.0.0</Data> 

  <Data>5335df9a</Data> 

  <Data>KERNELBASE.dll</Data> 

  <Data>6.1.7601.18409</Data> 

  <Data>53159a86</Data> 

  <Data>e0434352</Data> 

  <Data>0000c42d</Data> 

  <Data>408</Data> 

  <Data>01cfebb6f2ee8b4b</Data> 

  <Data>C:\Program Files (x86)\NPVR\NRecord.exe</Data> 

  <Data>C:\Windows\syswow64\KERNELBASE.dll</Data> 

  <Data>472fcdc3-57f4-11e4-b3d6-000dfe7e008d</Data> 

  </EventData>

  </Event>

mvallevand · 2014-10-27, 01:12 AM

If I had to guess I think you were too eager to hit delete after cancel, that second thread [3] DeleteRecording(106160) shouldn't start until [10] is finished

Code:
2014-10-26 18:32:42.302    [DEBUG][3]    CancelRecording(106160)

2014-10-26 18:32:42.302    [DEBUG][3]    queueing (106160) for cancellation

2014-10-26 18:32:42.578    [DEBUG][10]    recording service dequeued request to cancel (106160)

2014-10-26 18:32:42.585    [DEBUG][10]    StopStream(1)

2014-10-26 18:32:42.585    [DEBUG][10]    Stopping graph

2014-10-26 18:32:42.585    [DEBUG][10]    SetTarget@2

2014-10-26 18:32:42.806    [DEBUG][3]    DeleteRecording(106160)

2014-10-26 18:32:46.585    [DEBUG][10]    Graph stopping...

2014-10-26 18:32:46.690    [DEBUG][10]    Graph stopped

2014-10-26 18:32:46.690    [DEBUG][10]    Removing filter  NPVR Writer

2014-10-26 18:32:46.690    [DEBUG][10]    Removing filter  NPVR Net Push Source

2014-10-26 18:32:46.791    [DEBUG][10]    Executing: C:\Program Files\Silicondust\HDHomeRun\hdhomerun_config.exe 131C54E9 set /tuner0/channel none

2014-10-26 18:32:46.851    [DEBUG][10]    No C:\Users\Public\NPVR\Scripts\PostCancel.bat

2014-10-26 18:32:47.851    [DEBUG][3]    DeleteRecording@1

2014-10-26 18:32:47.851    [DEBUG][3]    Cancelling wake up request for for 'RecordingOID106160'

2014-10-26 18:32:47.851    [DEBUG][3]     -removing: D:\NPVR Recordings\NFL Football\NFL Football_20141026_15251830.ts

2014-10-26 18:32:47.851    [DEBUG][10]    recording service dequeued request to cancel (106160)

2014-10-26 18:32:48.543    [DEBUG][3]    DeleteRecording@2

Martin

johnsonx42 · 2014-10-27, 01:20 AM

I wonder if this is the same as the race-condition that can develop when I attempt to simultaneously cancel and delete an in-progress recording with the record button (ctrl-k)? Awhile back we had discussion and patches for this scenario but I found it was still possible to kill NRecord by doing that. I just decided never to do that again. (besides, on my system it's impossible to do it anyway, comskip will always have the file open for a few seconds after the recording ends so the delete would fail)

mvallevand · 2014-10-27, 01:23 AM

Brett I think you did use Record to Cancel/Delete right in the MVP.log I saw

2014-10-26 18:32:41.030 [DEBUG][3] User pressed: K

Martin

BrettB · 2014-10-27, 01:27 AM

mvallevand Wrote:Brett I think you did use Record to Cancel/Delete right in the MVP.log I saw

2014-10-26 18:32:41.030 [DEBUG][3] User pressed: K

Martin

I'm guessing that you are correct. I do normally use the Record button to delete recordings from the recording list.

Reddwarf · 2014-10-27, 05:18 PM

johnsonx42 Wrote:I wonder if this is the same as the race-condition that can develop when I attempt to simultaneously cancel and delete an in-progress recording with the record button (ctrl-k)? Awhile back we had discussion and patches for this scenario but I found it was still possible to kill NRecord by doing that. I just decided never to do that again. (besides, on my system it's impossible to do it anyway, comskip will always have the file open for a few seconds after the recording ends so the delete would fail)

I just saw the same here today. No entry in Nrecord.log except that it attempted to cancel the ongoing recording.

Possibly Related Threads…
Thread		Author	Replies	Views	Last Post
	NRecord Crashing	BrettB	1	1,058	2018-06-22, 03:08 AM Last Post: sub
	Intermittent NRecord Crash When Changing Channels (using Kodi)	mutichip	22	6,164	2018-06-10, 05:05 PM Last Post: mutichip
	immediate NRecord crash on 4.05 > 4.10 upgrade	shaunpatrick77	6	2,160	2018-03-05, 08:38 PM Last Post: KyleC_USA
	NRecord broken and I'm digging deeper...	macgyver	23	7,305	2017-12-03, 04:56 PM Last Post: macgyver
	Colossus dying?	mattyb	11	4,401	2017-11-10, 09:40 PM Last Post: steve232
	NRecord.exe fails with exception	gymshoe	9	3,130	2017-09-28, 07:14 PM Last Post: sub
	Errors in NRecord.log	BrettB	0	1,265	2017-09-24, 12:54 AM Last Post: BrettB
	NRecord.exe	jcole998	3	1,570	2017-05-25, 01:09 PM Last Post: jcole998
	Small NRecord.log issue	BrettB	1	1,121	2017-04-23, 06:26 PM Last Post: sub
	NRecord.exe High CPU Utilization	DParsons	32	9,260	2017-01-21, 10:11 PM Last Post: DParsons