graph stop crash still kills NRecord [FIXED!]

[johnsonx42]

Sub,

I got my first 2.3.6 graph stop crash last night, and it still took out NRecord. The difference now is that all of NRecord hung; before 2.3.6 some of it would still survive, like the EPG update routine. You can see from last night's log that it just stopped doing anything at 2am.

I do have the patch you posted to get rid of the crash.mdmp pop-up, so I got a crash.mdmp but no interactive services pop-up.

When I looked at the task manager after the crash, neither NRecord nor NDigitalHost were running.

Logs attached.

[sub]

I've never been able to reproduce the problem, so I've never been able to test the exact behaviour when the fault occurs. I'm fairly sure the attached will stop it bringing down nrecord.exe. It adds protection in nrecord.exe to protect against remote invocation exceptions, and simply log them. I didnt think of adding this when I was working on it, but it's definitely needed.

[johnsonx42]

thanks... installing now.

[johnsonx42]

It worked! It couldn't stop the graph to end Star Trek:TNG at 1:00am, the NDigitalHost died, it logged the exception and spun up a new NDigitalHost to record SouthPark at 1:00am like nothing happened. The recording is fine, post-processed and everything; I would have never even noticed anything had happened except that I happened to look in C:\temp and saw the crash.mdmp. Kudos! (crash.mdmp attached in case it contains anything interesting)

NRecord.log:

2012-01-26 00:00:00.223	[DEBUG][7]	allocating recording target filename: F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts
2012-01-26 00:00:00.223	[DEBUG][7]	About to start recording (146224): F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts
2012-01-26 00:00:00.223	[DEBUG][7]	Asking NDigitalHost to start: F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts
2012-01-26 00:00:01.481	[DEBUG][7]	Temp at 1/26/2012 12:00:11 AM
2012-01-26 00:00:01.481	[DEBUG][7]	Started recording (146224:F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts)
2012-01-26 00:00:01.528	[DEBUG][7]	Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts" 6 146224 1522
2012-01-26 01:00:00.083	[DEBUG][7]	Stopping recording (146224). Past end time of recording.
2012-01-26 01:00:00.169	[DEBUG][7]	StopStream
2012-01-26 01:00:22.482	[ERROR][7]	Unexpected stopping remote stream: System.Runtime.Remoting.RemotingException: Failed to read from an IPC Port: The pipe has been ended.


Server stack trace: 
   at System.Runtime.Remoting.Channels.Ipc.IpcPort.Read(Byte[] data, Int32 offset, Int32 length)
   at System.Runtime.Remoting.Channels.Ipc.PipeStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Runtime.Remoting.Channels.SocketHandler.ReadFromSocket(Byte[] buffer, Int32 offset, Int32 count)
   at System.Runtime.Remoting.Channels.SocketHandler.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.Runtime.Remoting.Channels.SocketHandler.ReadAndMatchFourBytes(Byte[] buffer)
   at System.Runtime.Remoting.Channels.Tcp.TcpSocketHandler.ReadAndMatchPreamble()
   at System.Runtime.Remoting.Channels.Tcp.TcpSocketHandler.ReadVersionAndOperation(UInt16& operation)
   at System.Runtime.Remoting.Channels.Ipc.IpcClientHandler.ReadHeaders()
   at System.Runtime.Remoting.Channels.Ipc.IpcClientTransportSink.ProcessMessage(IMessage msg, ITransportHeaders requestHeaders, Stream requestStream, ITransportHeaders& responseHeaders, Stream& responseStream)
   at System.Runtime.Remoting.Channels.BinaryClientFormatterSink.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.StopStream(Int32 streamHandle)
   at NShared.DigitalRecorder.StopStream(Int32 streamHandle)
2012-01-26 01:00:22.615	[DEBUG][7]	Starting: C:\Users\Public\NPVR\Scripts\PostProcessing.bat "F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts" 6 146224 1522
2012-01-26 01:00:22.638	[DEBUG][7]	allocating recording target filename: F:\Recordings\South Park\South Park_20120126_01000130.ts
2012-01-26 01:00:22.638	[DEBUG][7]	About to start recording (146143): F:\Recordings\South Park\South Park_20120126_01000130.ts
2012-01-26 01:00:22.638	[DEBUG][7]	Starting digital host
2012-01-26 01:00:25.136	[DEBUG][7]	Asking NDigitalHost to start: F:\Recordings\South Park\South Park_20120126_01000130.ts
2012-01-26 01:00:26.571	[DEBUG][7]	Temp at 1/26/2012 1:00:36 AM
2012-01-26 01:00:26.571	[DEBUG][7]	Started recording (146143:F:\Recordings\South Park\South Park_20120126_01000130.ts)
2012-01-26 01:00:26.633	[DEBUG][7]	Starting: C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat "F:\Recordings\South Park\South Park_20120126_01000130.ts" 13 146143 1522

NDigitalHost.log.1:

2012-01-26 00:00:00.223	[INFO][10]	DigitalRecorder.StartStream(F:\Recordings\Star Trek The Next Generation\Star Trek The Next Generation_20120126_00000100.ts)
2012-01-26 00:00:00.223	[INFO][10]	Creating BDA graph
2012-01-26 00:00:00.262	[DEBUG][10]	Using tuner Hauppauge WinTV 885 BDA Tuner/Demod (1)
2012-01-26 00:00:00.278	[DEBUG][10]	About to auto detect capture filter
2012-01-26 00:00:00.278	[DEBUG][10]	Got capture filter: 'Hauppauge WinTV 885 TS Capture'
2012-01-26 00:00:00.278	[DEBUG][10]	Added capture filter
2012-01-26 00:00:00.286	[DEBUG][10]	Connected Tuner to Capture
2012-01-26 00:00:00.309	[DEBUG][10]	EIT collection disabled
2012-01-26 00:00:00.309	[DEBUG][10]	Graph filter list:
2012-01-26 00:00:00.309	[DEBUG][10]	 - MPEG-2 Sections and Tables
2012-01-26 00:00:00.309	[DEBUG][10]	 - BDA MPEG2 Transport Information Filter
2012-01-26 00:00:00.309	[DEBUG][10]	 - MPEG-2 Demultiplexer
2012-01-26 00:00:00.309	[DEBUG][10]	 - NPVR TS Mon
2012-01-26 00:00:00.309	[DEBUG][10]	 - Capture
2012-01-26 00:00:00.309	[DEBUG][10]	 - Tuner
2012-01-26 00:00:00.309	[DEBUG][10]	 - Network Provider
2012-01-26 00:00:00.309	[INFO][10]	About to start BDA graph
2012-01-26 00:00:00.309	[DEBUG][10]	Starting graph...
2012-01-26 00:00:00.411	[DEBUG][10]	About to tune BDA graph: 
<tuning>
  <type>ATSC</type>
  <locator>
    <physical_channel>32</physical_channel>
  </locator>
  <service_id>1</service_id>
  <tsid>231</tsid>
  <service_type>1</service_type>
</tuning>

2012-01-26 00:00:01.458	[DEBUG][10]	Calling LockChannel()
2012-01-26 00:00:01.473	[DEBUG][10]	locked=1, present=1, strength=-10000, quality=100   (took 15ms to check)
2012-01-26 00:00:01.481	[INFO][10]	DigitalRecorder.StartStream() allocated handle: 0x1A
2012-01-26 00:00:01.481	[DEBUG][10]	Temp at 1/26/2012 12:00:11 AM
2012-01-26 01:00:00.169	[INFO][10]	DigitalRecorder.StopStream() handle: 1A
2012-01-26 01:00:00.169	[INFO][10]	No more streams active. Stopping device.
2012-01-26 01:00:00.169	[DEBUG][10]	About to request async graph stop
2012-01-26 01:00:00.169	[DEBUG][16]	Graph stopping... (async)
2012-01-26 01:00:08.169	[DEBUG][10]	Async stop taking way too long
2012-01-26 01:00:08.169	[DEBUG][10]	Removing filter  MPEG-2 Sections and Tables
2012-01-26 01:00:08.169	[DEBUG][10]	Removing filter  BDA MPEG2 Transport Information Filter
2012-01-26 01:00:08.169	[DEBUG][10]	Removing filter  MPEG-2 Demultiplexer

NDigitalHost.log:

[...startup]
2012-01-26 01:00:24.614	[INFO][1]	DigitalRecorder.StartHost()
2012-01-26 01:00:24.614	[INFO][1]	Starting remoting service
2012-01-26 01:00:24.620	[DEBUG][1]	Remoting started...
2012-01-26 01:00:24.683	[DEBUG][1]	Found parent process: NRecord
2012-01-26 01:00:25.290	[INFO][4]	DigitalRecorder.StartStream(F:\Recordings\South Park\South Park_20120126_01000130.ts)
2012-01-26 01:00:25.290	[INFO][4]	Creating BDA graph
2012-01-26 01:00:25.329	[DEBUG][4]	Using tuner Hauppauge WinTV 885 BDA Tuner/Demod (1)
2012-01-26 01:00:25.352	[DEBUG][4]	About to auto detect capture filter
2012-01-26 01:00:25.360	[DEBUG][4]	Got capture filter: 'Hauppauge WinTV 885 TS Capture'
2012-01-26 01:00:25.360	[DEBUG][4]	Added capture filter
2012-01-26 01:00:25.360	[DEBUG][4]	Connected Tuner to Capture
2012-01-26 01:00:25.399	[DEBUG][4]	EIT collection disabled
2012-01-26 01:00:25.399	[DEBUG][4]	Graph filter list:
2012-01-26 01:00:25.399	[DEBUG][4]	 - MPEG-2 Sections and Tables
2012-01-26 01:00:25.399	[DEBUG][4]	 - BDA MPEG2 Transport Information Filter
2012-01-26 01:00:25.399	[DEBUG][4]	 - MPEG-2 Demultiplexer
2012-01-26 01:00:25.399	[DEBUG][4]	 - NPVR TS Mon
2012-01-26 01:00:25.399	[DEBUG][4]	 - Capture
2012-01-26 01:00:25.399	[DEBUG][4]	 - Tuner
2012-01-26 01:00:25.399	[DEBUG][4]	 - Network Provider
2012-01-26 01:00:25.399	[INFO][4]	About to start BDA graph
2012-01-26 01:00:25.399	[DEBUG][4]	Starting graph...
2012-01-26 01:00:25.493	[DEBUG][4]	About to tune BDA graph: 
<tuning>
  <type>ATSC</type>
  <locator>
    <physical_channel>13</physical_channel>
  </locator>
  <service_id>3</service_id>
  <tsid>301</tsid>
  <service_type>1</service_type>
</tuning>

2012-01-26 01:00:26.532	[DEBUG][4]	Calling LockChannel()
2012-01-26 01:00:26.547	[DEBUG][4]	locked=1, present=1, strength=-10000, quality=100   (took 32ms to check)
2012-01-26 01:00:26.555	[INFO][4]	DigitalRecorder.StartStream() allocated handle: 0x1
2012-01-26 01:00:26.555	[DEBUG][4]	Temp at 1/26/2012 1:00:36 AM

[sub]

Awesome!

Thanks for the confirmation.

[johnsonx42]

The only tiny downside now to a graph stop crash is that it takes about 22 seconds for it to crash and a few more seconds to spin up a new NDigitalHost and get the next recording going. I know you had added code in the past that put in extra delays and further attempts to force the graph to stop which now just delay the smooth recovery. Would there be any point in looking at some of that code to tighten it up again, or is this one of those 'leave well enough alone' situations?

[sub]

That time is almost certainly the generation of the crash.mdmp, or at least the majority of it.

[johnsonx42]

something seems to have broken somewhere between then and now. I got a graph-stop hang tonight when my wife tried to watch live tv on channel 7; she got a blank screen, so she quit live tv and that's when the graph hung. she tried again, and then it got really stuck. no crash.mdmp was written, and that instance of ndigitalhost.exe (1524) is completely stuck. I tried ending the process, but it won't die. nrecord is stuck too, the recording that was to end at 10pm (House) just kept going until I shutdown NRecord. I'm just about to reboot...

any ideas?

(edit: I do have to acknowledge though that this particular graph hang may be a little different than the one that plagued me and others for so long. this seems to be a graph that never started right in the first place, hence the blank screen when watching live tv, while the one I logged above was for a graph that formed normally and recorded successfully, but hung/crashed trying to shut down. so maybe I shouldn't have resurrected this thread for this... I dunno)

(edit 2: kudos though on the improved handling of recordings-in-progress when NRecord stops or crashes; the House recording was marked "Recording Service stopped during Recording", but can be Played from Recordings just the same as any other recording. In previous releases this recording would have been marked "Recording Service not running at recording time", and the Play option would have been unavailable. Nice.)

[sub]

something seems to have broken somewhere between then and now. I got a graph-stop hang tonight when my wife tried to watch live tv on channel 7; she got a blank screen, so she quit live tv and that's when the graph hung. she tried again, and then it got really stuck. no crash.mdmp was written, and that instance of ndigitalhost.exe (1524) is completely stuck. I tried ending the process, but it won't die. nrecord is stuck too, the recording that was to end at 10pm (House) just kept going until I shutdown NRecord. I'm just about to reboot...

If the process is unable to be killed, it's probably executing a driver call. Hard to know for sure though.

[jpsa]

Windows Vista & Windows 7 let you right-click a process in task manager and select "Create Dump File". Might that help to diagnose hangs like this?