2AM Crash

[jcjefferies]

I have had a problem for several weeks with my Vista NPVR server often crashing around 2AM since I bought a new twin USB tuner. The problem only seems to happen if a recording is being made while EPG update is running and I managed to catch the logs for the first time. To help diagnose the problem I am using my old Kworld UB 450-T which has never caused a problem as the first tuner and half of the Twin tuner UB499-2T(IT9135) as the second tuner with the other half disabled.

The UB450-T tuner recorded a programme 1:35 – 2:05 and although NPVR says the recording “Failed because record service was not running” it was recorded and is watchable to the end. NRecord.log has the start of recording but it should have finished at 2:08 with padding but NRecord seems to have died at 2:07. “Date Modified” for the file gives the time as 2:09

At 2:01 the enabled half of the new twin tuner starts EPG update but stops at 2:07 when NRecord must have crashed. In the morning NPVR was still “Recording” although the file was not modified after 2:09 and NRecord was not running. Restarting NPVR and the NPVR service got everything working but an unknown process was stopping the computer sleeping so a reboot was need.

NRecord .log is enclosed but NPVR.log has nothing but “Stopping Windows Screen Saver Starting “ every second from 1am to 4am. If there is only one tuner and it is set to do a recording around 2am is “EPG update” delayed or cancelled. Tonight another recording takes place around the same time as an EPG update, but because other recordings are being made before 2am the other tuner may do the EPG update this time so may give different results.

[johnsonx42]

Code:

2011-08-26 02:06:58.109    [INFO][8]    DigitalRecorder.StopStream() handle: F
2011-08-26 02:06:58.109    [INFO][8]    No more streams active. Stopping device.
2011-08-26 02:06:58.109    [DEBUG][8]    About to request async graph stop
2011-08-26 02:06:58.109    [DEBUG][29]    About to stop network provider
2011-08-26 02:06:58.309    [DEBUG][29]    Stopped network provider
2011-08-26 02:06:58.309    [DEBUG][29]    Graph stopping... (async)
2011-08-26 02:07:06.109    [DEBUG][8]    Async stop taking way too long
2011-08-26 02:07:06.109    [DEBUG][8]    Removing filter  MPEG-2 Sections and Tables
2011-08-26 02:07:06.110    [DEBUG][8]    Removing filter  BDA MPEG2 Transport Information Filter
2011-08-26 02:07:06.110    [DEBUG][8]    Removing filter  MPEG-2 Demultiplexer
.....that's all she wrote.....

the fact that more people are starting to see this graph-won't-stop problem is good news for me, as sub will have more scenarios and data points from which to derive a solution, but understandably a bummer for those having the problem and no doubt an irritation for sub since the crash seems to occur outside of his code.

@jcjeffries: you'll want to make sure you have a c:\temp directory, wherein NRecord MAY write a crash.mdmp file. also, as sub is on the cusp of a new release, you will likely have to wait until the new release as the debug symbols in any crash.mdmp created now won't match up with sub's current dev code.

Restarting NPVR and the NPVR service got everything working but an unknown process was stopping the computer sleeping so a reboot was need.

I suspect if you had looked in the Task Manager, you would have found there were two NRecords running at that point - the new instance you started after the crash, and a crashed instance of it stopping sleep.

[jcjefferies]

There was a crash dump in \temp but from 8 days ago when I was still setting up the new server. I do seem to remember a dump when I test scheduled 2 recordings on different mux starting together.

The tray icon was red but the Status box was blank so I sorted "Processes" and looked at the "N"s and NPVR.exe was the only process running so I stopped it before starting it and NRecord.

A recording is scheduled tonight past 2am but I think the tuners will swap tasks tonight so it will be interesting if NRecord still crashes.

[johnsonx42]

unfortunately it doesn't write a dump every time, it seems to depend on the exact scenario of the crash. as to multiple NRecords running, that was just my theory; after some crashes I see a situation where it's possible to restart NRecord, and it appears to work ok, yet there will be an orphan instance of it still in the task list so I thought that might have been your situation as well.

[jcjefferies]

The problem has only happened overnight around EPG update and only when there are 2 tuners enabled. However it could be just that the new tuner is more prone to the problem.

A very similar situation last night to the previous night with the same tuner recording right through the EPG update period but this time everything worked correctly. EPG update started at 2:01:30 and the scan completes at 2:07:00 then starts shutting down processes but this time the Graph stops and it was able to complete the EPG update. Tonight there are no scheduled recordings around 2am so a different tuner will do the EPG update tonight. It seems probable that the problem is related to the tuner during EPG updates and the fact that recordings are happening during this time may not be relevant.

[jcjefferies]

The suspicion was that my new twin tuner was causing the problem or at least was more susceptible to the problem. The problem has not happened at EPG update time for almost a week which covers the period before and after the update to 2.2.6. So today I did a manual EPG update on my Vista server and crashed as before at the end of the scanning phase as before with the same error.

2011-08-26 02:06:58.309 [DEBUG][29] Graph stopping... (async)
22011-08-26 02:07:06.109 [DEBUG][8] Async stop taking way too long

I have since run EPG update 12 times and of those 9 were successful and 3 crashed NPVR. However for the first 6 the failure rate was 50% but the next 6 were 100% successful. The only thing different was that a recording was playing on the client during updates 7-9!

[jcjefferies]

Last night another 2am crash with slightly different symptoms. This morning a recording 01:15 – 02:05 is still listed as “Recording” and four programmes it should have recorded are still listed as “Pending”. NPVR.exe and Ntray.exe are both running but no Nrecord .exe. It seems to be a variation of the 2am crash I have previously reported at the end of scan phase of EPG update.

At 02:01:57 a recording is still taking place when it starts updating the EPG but the log lists 5 “Failed to start device” errors after which it sets about setting the scheduled recordings, presumably using the old EPG data. At 02:08 the recording underway completed after the 3 minute padding and the recording shut down started but failed with “Async stop taking way too long”. However the recording still listed as “Recording” terminated at 2:08 and although listed as a failed recording, a complete recording has been saved to disk. One odd thing is there is no mention anywhere in the log of the second tuner which I think usually does the EPG update. Perhaps it failed and was not available but there is no mention in the logs.

There is nothing in the Windows logs although the previous night at 02:03 there is a .Net error and Nrecord.exe shuts down. However there was no indication the next morning of an NPVR problem but the logs for that time had been overwritten.