recording service hung trying to stop a graph

[johnsonx42]

This morning I found my 2:00am recording still showing as "Recording", and no other recordings had occurred since then. There apparently was a problem with the graph, as it created a zero-length file. However NRecord got itself stuck trying to kill the graph, and never recoverd. Here is the relevant bit of log, but the full log is attached.

Code:

2010-08-28 02:00:01.413    [DEBUG][6]    About to start recording (5849): F:\Recordings\The PokerStars.net Big Game\The PokerStars.net Big Game_20100828_02000300.ts
2010-08-28 02:00:01.413    [INFO][6]    DigitalRecorder.StartStream(F:\Recordings\The PokerStars.net Big Game\The PokerStars.net Big Game_20100828_02000300.ts)
2010-08-28 02:00:01.413    [INFO][6]    Creating BDA graph
2010-08-28 02:00:01.420    [DEBUG][6]    Using tuner WinTV HVR-950 BDA Tuner (1)
2010-08-28 02:00:01.436    [DEBUG][6]    About to auto detect capture filter
2010-08-28 02:00:01.436    [DEBUG][6]    Got capture filter.
2010-08-28 02:00:01.436    [DEBUG][6]    Added capture filter
2010-08-28 02:00:01.444    [DEBUG][6]    Connected Tuner to Capture
2010-08-28 02:00:01.459    [DEBUG][6]    Graph filter list:
2010-08-28 02:00:01.459    [DEBUG][6]     - BDA MPEG2 Transport Information Filter
2010-08-28 02:00:01.459    [DEBUG][6]     - MPEG-2 Demultiplexer
2010-08-28 02:00:01.459    [DEBUG][6]     - NPVR TS Mon
2010-08-28 02:00:01.459    [DEBUG][6]     - Capture
2010-08-28 02:00:01.459    [DEBUG][6]     - Tuner
2010-08-28 02:00:01.459    [DEBUG][6]     - Network Provider
2010-08-28 02:00:01.459    [INFO][6]    About to start BDA graph
2010-08-28 02:00:01.459    [DEBUG][6]    Starting graph...
2010-08-28 02:00:05.186    [DEBUG][6]    About to tune BDA graph:
<tuning>
  <type>ATSC</type>
  <locator>
    <physical_channel>11</physical_channel>
  </locator>
  <service_id>3</service_id>
  <tsid>299</tsid>
  <service_type>1</service_type>
</tuning>

2010-08-28 02:00:05.499    [DEBUG][6]    locked=1, present=1, strength=-29, quality=78   (took 78ms to check)
2010-08-28 02:00:05.514    [INFO][6]    DigitalRecorder.StartStream() allocated handle: 0x59
2010-08-28 02:00:05.514    [DEBUG][6]    Temp at 8/28/2010 2:00:15 AM
2010-08-28 02:00:05.514    [DEBUG][6]    Started recording (5849:F:\Recordings\The PokerStars.net Big Game\The PokerStars.net Big Game_20100828_02000300.ts)
2010-08-28 02:00:05.624    [DEBUG][6]    No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2010-08-28 03:00:00.352    [DEBUG][6]    Stopping recording (5849). Past end time of recording.
2010-08-28 03:00:00.352    [INFO][6]    DigitalRecorder.StopStream() handle: 89
2010-08-28 03:00:00.360    [INFO][6]    No more streams active. Stopping device.
2010-08-28 03:00:00.360    [DEBUG][6]    Graph stopping...

The "Graph stopping..." message is it... no "Graph stopped", no "Removing filter" messages. After this point in the log the only other thing it did was the EPG update, but did not "Reload the Recording Schedule". A half-dozen recordings where missed until I restarted the recording service a little before 10:00am.

I removed detail about a 30 minute recording that started at 2:00am as well, and ended normally at 2:30am just to keep the excerpt concise. It's in the attached full log of course.

Would it possible to add more logging detail to determine exactly why it couldn't stop the graph, and/or add some code to get it to recover from this condition instead of going into a coma?

By the way, a quick aside, it is a little confusing to have the stream handle reported in hex when it starts, but decimal when it ends (but yes, I do know that 0x59=89).

[sub]

Would it possible to add more logging detail to determine exactly why it couldn't stop the graph, and/or add some code to get it to recover from this condition instead of going into a coma?

There is no obvious cause shown in the log. I remember there used to be the occasional report of this with GBPVR aswell, but I was never able to reproduce it. My suspicion is some driver bug is occassionally cause things to lock up when the device is ask to stop, and the call never returns. There is only one line of code between the "Graph stopping..." (which does appear) and "Graph stopped" (which doesnt appear) log messages, and this line is asking the device to stop.

When its in that state you could try right-clicking on nrecord.exe in the task manager and selecting create dump from the context menu, then putting it somewhere I can download from. It might give some more clues.

[mvallevand]

This is the problem I have been reporting for awhile now dieing at Graph Stopping.. I never had this happen on GBPVR.

Martin

[sub]

This is the problem I have been reporting for awhile now dieing at Graph Stopping.. I never had this happen on GBPVR.

Post your log and I'll see if it looks the same.

[johnsonx42]

I did have this happen from time to time with GB-PVR as well. I uploaded a dump for you once then, but of course that was at the end of good ol' GB-PVR.

I'll create a dump the next time this happens. I'll also keep track of whether it happens always on the same tuner; it was my HVR-850 this time (which identifies itself as an HVR-950 with current drivers).