NRecord.exe Crash After Web Streaming

[kayleigh]

Basically, the short version of an issue I'm having, is when I stop streaming video through NEWA, NRecord.exe crashes and the recording service restarts. I've replicated the issue a couple of times - please let me know if you need more logs. There's no crash file in c:\temp.

This is from the Windows App Log:

Source: ASP.NET 2.0.50727.0
Event: 1334

An unhandled exception occurred and the process was terminated.

Application ID: NRecord.exe

Process ID: 3408

Exception: System.Collections.Generic.KeyNotFoundException

Message: The given key was not present in the dictionary.

StackTrace:    at System.ThrowHelper.ThrowKeyNotFoundException()
   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.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

I've applied all NPVR R1 patches and NEWA code patches up through today (28 Feb 2012 in my part of the world). I haven't applied the pre-R2 patch yet. I'm running Windows 7 Ultimate x64 in case that matters.

Thanks for taking a look at this for me!

[UncleJohnsBand]

Need to know specifics.....

Where are you streaming from.....live tv from the guide via the details pop-up or from a recorded show in manage recordings or from your video library?
What stream settings are you using - preset or custom? If custom, what are all the parameters

[kayleigh]

I'm streaming live TV from the Guide. I select the show name (click it), get the pop-up and select the Stream Now button, Best quality on the local network. Stream Player: VLC with the Open Stream in External Player selected. Video Bitrate: LAN. Video Size: Scale 1.00. Streamer Port: 7748. Streamer Buffer Size: 5000ms. Streamer Process Priority: Above Normal or Normal, no difference. Streamer Transcode Options: H264/MP4A/MPEG-TS.

The video capture source is component with optical audio cable input. The NRecord.exe crash happens just after I select Stop Server Stream, always the same error I listed above (different process ID). The crash doesn't happen when I stream recorded video.

Hopefully that everything you're asking for... let me know if you need anything else. Thanks!

PS: Oh, I haven't tried the CSS interface to see if I get the same errors. I'll try them and see if I get the same error.

PSS: Yep, same result.

[kayleigh]

I read through the main NEWA release thread and ended up on the VLC streaming problem thread. (http://forums.gbpvr.com/showthread.p...038#post424038 ) I changed the NPVR Service from Local Service account to the local admin account, but still no joy.

[UncleJohnsBand]

I'm streaming live TV from the Guide. I select the show name (click it), get the pop-up and select the Stream Now button, Best quality on the local network. Stream Player: VLC with the Open Stream in External Player selected. Video Bitrate: LAN. Video Size: Scale 1.00. Streamer Port: 7748. Streamer Buffer Size: 5000ms. Streamer Process Priority: Above Normal or Normal, no difference. Streamer Transcode Options: H264/MP4A/MPEG-TS.

The video capture source is component with optical audio cable input. The NRecord.exe crash happens just after I select Stop Server Stream, always the same error I listed above (different process ID). The crash doesn't happen when I stream recorded video.

Hopefully that everything you're asking for... let me know if you need anything else. Thanks!

PS: Oh, I haven't tried the CSS interface to see if I get the same errors. I'll try them and see if I get the same error.

PSS: Yep, same result.

Thanks...that gives me enough to start looking into this.

[UncleJohnsBand]

Give the attached patch a try.....I put a check in the player where I think the issue is occurring. This patch does both the standard player and the CSS based player.

Edit: Patch removed......see this post for final patch.

[kayleigh]

Sorry, I'm still getting the same error.

I rebooted a couple times and checked my .NET installation to make sure that isn't the cause, but it still happens when I stream live TV.

[UncleJohnsBand]

Sorry, I'm still getting the same error.

I rebooted a couple times and checked my .NET installation to make sure that isn't the cause, but it still happens when I stream live TV.

Can you also include the web.log file........

[UncleJohnsBand]

Can you also include the web.log file........

Dulp! I see the web.log is in the zip....thanks.

[UncleJohnsBand]

I can see the stream start from NEWA in the web log:

2012-03-02 01:53:08.448	[INFO][15]	VLC Path= C:\Program Files (x86)\VideoLAN\VLC\
2012-03-02 01:53:08.448	[INFO][15]	Args= -I http "D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts" :sout=#transcode{vcodec=h264,vb=1200,width=720,height=480,acodec=mp4a,ab=32,channels=2}:standard{access=http,mux=ts,dst=:7748} vlc://quit

I can see it start in the recording service as well:

2012-03-02 01:52:59.300	[DEBUG][7]	Requesting wake up for 'RecordingOID872' at 3/2/2012 1:30 AM
2012-03-02 01:52:59.305	[DEBUG][7]	allocating recording target filename: D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts
2012-03-02 01:52:59.306	[DEBUG][7]	About to start recording (872): D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts...
2012-03-02 01:52:59.370	[INFO][7]	HDPVRRecorder.StartStream(D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts)
2012-03-02 01:52:59.370	[INFO][7]	HDPVR stream count now 1
2012-03-02 01:52:59.370	[INFO][7]	Running blaster: C:\Program Files (x86)\NPVR\dtvTune.exe -ip 192.168.0.55 -channel 6
2012-03-02 01:53:01.793	[DEBUG][7]	About to tune graph to: 
<tuning>
  <type>HDPVR</type>
  <locator>
    <channel>6</channel>
    <input>0</input>
    <blaster_executable>C:\Program Files (x86)\NPVR\dtvTune.exe</blaster_executable>
    <blaster_args>-ip 192.168.0.55 -channel {channel}</blaster_args>
  </locator>
</tuning>

2012-03-02 01:53:01.793	[INFO][7]	Creating graph
2012-03-02 01:53:01.803	[DEBUG][7]	Building graph using: Hauppauge Colossus Crossbar 0 (92529544)
2012-03-02 01:53:01.841	[DEBUG][7]	setting video routing
2012-03-02 01:53:01.856	[DEBUG][7]	setting Colossus audio routing
2012-03-02 01:53:01.856	[DEBUG][7]	using 'Audio Line In'
2012-03-02 01:53:01.908	[DEBUG][7]	Graph filter list:
2012-03-02 01:53:01.909	[DEBUG][7]	 - NPVR Writer2
2012-03-02 01:53:01.909	[DEBUG][7]	 - NPVR Writer
2012-03-02 01:53:01.909	[DEBUG][7]	 - Infinite Pin Tee Filter
2012-03-02 01:53:01.909	[DEBUG][7]	 - Hauppauge Colossus TS Encoder 0
2012-03-02 01:53:01.909	[DEBUG][7]	 - Hauppauge Colossus Capture 0
2012-03-02 01:53:01.909	[DEBUG][7]	 - Hauppauge Colossus Crossbar 0
2012-03-02 01:53:01.909	[INFO][7]	About to start graph
2012-03-02 01:53:01.921	[DEBUG][7]	About to switch HDPVR/Colossus to target: 
D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts
2012-03-02 01:53:01.922	[DEBUG][7]	Temp at 3/2/2012 1:53:11 AM
2012-03-02 01:53:01.922	[DEBUG][7]	Started recording (872:D:\Recordings\ABC World News Now\ABC World News Now_20120302_01370500.ts)
2012-03-02 01:53:01.929	[DEBUG][7]	No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat

It appears that nrecord that is running NEWA crashes (assume) since the last entry in web.log1 is 1:53:35 and the next web log (web.log) has the first entry time of 1:54:38......

The nrecord log shows no issue....it just stops at 1:53:36......it receives the cancel requests from NEWA (there are 2....one to stop it and one to delete it) and they work fine .....so there is no report of the error you are seeing in the windows event log as posted in the first post within NPVR within the nrecord log.

2012-03-02 01:53:35.239	[DEBUG][6]	CancelRecording(872)
2012-03-02 01:53:35.239	[DEBUG][6]	queueing (872) for cancellation
2012-03-02 01:53:35.241	[DEBUG][6]	CancelRecording(872)
2012-03-02 01:53:35.241	[DEBUG][6]	queueing (872) for cancellation
2012-03-02 01:53:35.388	[DEBUG][7]	recording service dequeued request to cancel (872)
2012-03-02 01:53:35.396	[INFO][7]	HDPVRRecorder.StopStream(2)
2012-03-02 01:53:35.396	[INFO][7]	HDPVR/Colossus stream count now 0
2012-03-02 01:53:35.397	[DEBUG][7]	Graph stopping...
2012-03-02 01:53:35.959	[DEBUG][7]	Graph stopped
2012-03-02 01:53:35.962	[DEBUG][7]	Removing filter  NPVR Writer2
2012-03-02 01:53:35.962	[DEBUG][7]	Removing filter  NPVR Writer
2012-03-02 01:53:35.962	[DEBUG][7]	Removing filter  Infinite Pin Tee Filter
2012-03-02 01:53:35.963	[DEBUG][7]	Removing filter  Hauppauge Colossus TS Encoder 0
2012-03-02 01:53:35.964	[DEBUG][7]	Removing filter  Hauppauge Colossus Capture 0
2012-03-02 01:53:35.965	[DEBUG][7]	Removing filter  Hauppauge Colossus Crossbar 0
2012-03-02 01:53:36.268	[DEBUG][7]	recording service dequeued request to cancel (872)

The first entry in the new nrecord log is at 1:54:36 which aligns to the web.log time for the restart.

2012-03-02 01:54:36.412	[DEBUG][4]	OnStart()
2012-03-02 01:54:36.418	[INFO][4]	Using local in-process recording service
2012-03-02 01:54:36.621	[DEBUG][4]	RecordingServiceProxy@exit
2012-03-02 01:54:36.752	[INFO][4]	RecordingService.Startup()

Is the nrecord.exe file the same date/time stamp in both the web\bin directory as well as wherever you npvr data files are stored?