New Problem - Zombie Recording

[andrewj]

Hi,

I have either a new problem, or a new symptom of the issues which started after the recent move of BBC4.

Last night I attempted to record a program starting at 21:00. The recording started OK, as did several others in either overlapping slots or scheduled later. They all completed OK, but the BBC4 program never terminated properly, and was still "recording" at 6.30 this morning. A check on the NPVR device status didn't show anything active, but observing the recording directory over time I could see the last updated time changing and a very small amount of data being added (the channel is off the air at this time). The system reported the file as still open in NDigitalHost.exe.

Logs attached. I can see the recording starting at 20:57 on ndigitalhost-23.log. I can't see any obvious errors, but I can't see a final "Stop Host"... Nothing in the Windows event logs.

The program showed up properly in the guide, and the scheduled recording was from 20:57 to 22:04 as expected.

I have seen this problem once before, also from BBC4, so I do wonder if it something to do with the EPG data.

I manually restarted the NPVR recording service and the recording finally terminated allowing ongoing processing to proceed. For now I think I'll extend my "watcher" service to bounce the recording service manually at about 4am, but that's a work-around not a fix.

Any ideas?

Thanks
Andrew

[Bobins]

Your failed recording stop seems to be because of this error:-

2018-02-15 22:04:00.186 [ERROR][9] Unexpected stopping remote stream: System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.

Server stack trace:
at NShared.DigitalRecorder.StopStream(Int32 streamHandle)
at NDigitalHost.RecorderRemote.StopStream(Int32 streamHandle)
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.StopStream(Int32 streamHandle)
at NShared.DigitalRecorder.StopStream(Int32 streamHandle)
2018-02-15 22:04:00.186 [ERROR][9] Trying to force restart of NDigitalHost on next stream request...

Out-of-memory errors are not common occurrences and I'm not aware of NPVR having memory leaks (my system is heavily used and I don't have the problems you're seeing).

Are you running anything else other than NPVR on it?
Seen in a previous post "and could cause problems with other things running on my system".

Although you've previously said you have 14Gb of memory (an odd number!), it's only a lot if nothing else is using it.

My personal experience of Media systems especially one's recording TV is they work much better if the system is dedicated to them and not running lots of other "stuff"

[andrewj]

Hi. Thanks for looking.

I can't explain the out of memory error unless it's something in NPVR itself.

I'm comfortable that nothing else was consuming much memory at the time of recording, or overnight. I regularly run all sorts of stuff including development environments and VMs alongside NPVR and haven't had any problems until recently. For example although I have done various things on the system today Process Explorer reports that I'm only using 3.8GB, which leaves ~10GB spare. If NPVR can't work within that when only recording 2-3 programs then there's a problem.

The only heavy processing which occurs outside working hours is converting the recordings to MP4. This does run the CPU up to 100% (although the system remains perfectly usable for other tasks), but only adds about 1GB to the memory usage.

I don't believe I need to dedicate a system to NPVR. Something has recently started happening on my system which is causing problems but not of such a nature that they are affecting anything else or leaving any trace in the main event logs.

Any other ideas?
Andrew

[Bobins]

If NPVR had a generic memory problem/memory leak, I'm pretty sure it would be a regular topic in the forum.

My own system is often recording 3, 4 or 5 simultaneous and/or overlapping recordings and I've never seen problems like you're reporting. Whilst I may have 16Gb of RAM, I used to run the system with only 4Gb and it didn't have problems. I only increased the memory when I went to a 64bit OS and the journey to Windows 10.

This makes me suspect that it's not NPVR that is the root of the problem but either something else interacting with it or giving it a resource problem.

What O/S are you running? I notice you refer to running VMs and development environments?

Oh and I'm in the UK so already experiencing the re-tune of BBC4 challenges :mad:

Ray

[Graham]

... but the BBC4 program never terminated properly, and was still "recording" at 6.30 this morning.

I also had an "endless" recording a few weeks ago ... it only happened once and I can't remember if it was BBC4 or not. For me, it appears to have been a one time glitch. My suggestion would be to wait and see if it happens again.

[andrewj]

In answer to Graham, I'm running Windows 7-64. Everything else seems pretty stable.

I've just checked, and with 3 scheduled recordings active, CPU usage is about 6% and memory usage <4GB out of 14GB. This is definitely not a problem with other system load in any general terms.

I've had two endless recordings in a week, both on BBC4, but I don't have enough data to confirm whether that's just co-incidence.

[ALG]

I've been having lots of problems recording anything on com 7 and com 8 since the move of BBC4 HD:

Recordings not stopping, tuners disappearing from Device status so subsequent recordings failing.

This was also a problem for Panasonic equipment using com 7 and com 8 for a couple of weeks after the move, apparently this has now been rectified by changes to the transport stream but has not fixed my problems.

Because of this problem I tend to use my set top Boxes (Humax Foxsat HDR & HDR Fox T2 but tonight I tried a Top of the pops (BBC4 HD) which was due to finish at 23:10, plus 8 minutes padding but the file is still growing in size at 23:53.
On this occasion the Device status box is populated as normal.

Com 7 & Com 8 are to become SFNs (Single Frequency Networks) in March and they have increased the Guard Interval from 1/128 to 1/16 but I suspect they have been tinkering with other things too.

It has been suggested that the stream is carrying the EPG data for the whole country and this could be causing the problems!

I have 4 PCs that all suffer this same problem. Although message says out of memory, I think it's the memory allocated to the service as I have 16GB Ram and only 25% in use, a bit like with Windows 9x that had heaps and stacks that would overflow.

Here is part of the log file that looks relevant and you'll see an out of memory error on the last line:

2018-02-17 22:31:00.224 [DEBUG][9] allocating recording target filename: D:\Recording 2\Top of the Pops 1985_20180217_22352310.ts
2018-02-17 22:31:00.224 [DEBUG][9] About to start recording (6777 on 48): D:\Recording 2\Top of the Pops 1985_20180217_22352310.ts...
2018-02-17 22:31:00.224 [DEBUG][9] Free space 304368705536 (D:\)
2018-02-17 22:31:00.224 [DEBUG][9] Starting digital host
2018-02-17 22:31:01.100 [DEBUG][9] Allocating IPC channel
2018-02-17 22:31:01.100 [DEBUG][9] Registering channel
2018-02-17 22:31:01.101 [DEBUG][9] About to get: ipc://DigitalHost-48/RecorderRemote
2018-02-17 22:31:01.101 [DEBUG][9] Got: ipc://DigitalHost-48/RecorderRemote
2018-02-17 22:31:01.102 [DEBUG][9] Asking NDigitalHost to start: D:\Recording 2\Top of the Pops 1985_20180217_22352310.ts
2018-02-17 22:31:03.121 [DEBUG][9] Temp at 17/02/2018 22:31:13
2018-02-17 22:31:03.121 [DEBUG][9] Started recording (6777:1:\Recording 2\Top of the Pops 1985_20180217_22352310.ts)
2018-02-17 22:31:03.128 [DEBUG][9] No C:\Users\Public\NPVR\Scripts\ParallelProcessing.bat
2018-02-17 22:31:03.132 [DEBUG][116] catalog says:
<Catalog><Version>1</Version><Description>John Peel and Janice Long present the pop chart programme, from 11 April 1985. Featuring Tears for Fears, The Rah Band, Dream Academy, King and Philip Bailey &amp; Phil Collins. [S]</Description><Episodes></Episodes></Catalog>
2018-02-17 22:31:03.676 [ERROR][74] Unexpected error looking up metadata: System.NullReferenceException: Object reference not set to an instance of an object.
at NShared.TheTVDBMetadataPlugin.LookupMetadata(MetadataEntity entity)
2018-02-17 22:31:03.676 [DEBUG][116] Downloading metadata and artwork took + 544.025ms
2018-02-17 23:18:00.047 [DEBUG][9] Stopping recording (6777 on 48). Past end time of recording. 1
2018-02-17 23:18:00.055 [DEBUG][9] StopStream(1)
2018-02-17 23:18:00.072 [ERROR][9] Unexpected stopping remote stream: System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.

Andrew

[andrewj]

It's definitely a problem with BBC4 and/or how NPVR is handling it.

I had not one but three failures last night, as I was recording three separate BBC4 programs. A BBC1 program recorded OK, except for the fact that the failure at the end of the first BBC4 program crashed the recording service and it took a minute for my "watcher" service to restart it.

Same items in the event log as in Bobins' post above - basically NRecord gets an out of memory error. In last night's case it was sufficient to then cause some other apps to crash as a result, but that wasn't the case earlier in the week when I only had one fault.

Assuming Andrew (ALG) is right and there's a problem with the EPG data, is there any way to fix / work around this?

Thanks
Andrew

[ALG]

It's definitely a problem with BBC4 and/or how NPVR is handling it.

Not exclusively BBC4 HD but any channel on com 7 or com 8, I get exactly the same problems with channel 4 +1 and that's on com 7.

There's a lot I like on BBC4 HD and I may try recording everything from 7PM (when it comes on air) till around 3AM (when broadcasting ends). Rebooting in the morning, or using andrewj's " RestarterService" app.

[Graham]

I've been having lots of problems recording anything on com 7 and com 8 since the move of BBC4 HD:

It's definitely a problem with BBC4 and/or how NPVR is handling it.

I recorded shows on BBC4 HD last night and the recordings playback without incident ... but, the nrecord.log.2 has ...

2018-02-17 21:49:00.081 [DEBUG][9] Stopping recording (87236 on 41). Past end time of recording. 1
2018-02-17 21:49:00.367 [DEBUG][9] StopStream(1)
2018-02-17 21:49:02.253 [ERROR][9] Unexpected stopping remote stream: System.Runtime.Remoting.RemotingException: Failed to read from an IPC Port: The pipe has been ended.

and the ndigitalhost-41.log has this ...

2018-02-17 21:49:01.075 [INFO][5] No more streams active. Stopping device.
2018-02-17 21:49:01.107 [DEBUG][5] About to request async graph stop
2018-02-17 21:49:01.153 [DEBUG][5] unexpected=-1
2018-02-17 21:49:01.153 [DEBUG][5] Stop() appeared to have failed. Exiting...
2018-02-17 21:49:01.175 [DEBUG][5] Unregistering IPC host
2018-02-17 21:49:01.213 [INFO][5] DigitalRecorder.StopHost()
2018-02-17 21:49:01.255 [DEBUG][5] Trying CloseMainWindow()
2018-02-17 21:49:01.337 [DEBUG][5] Trying Application.Exit()
2018-02-17 21:49:01.371 [DEBUG][5] Trying Environment.Exit()

A cutchunk of the last 100 Meg of the recording is at ... https://www.dropbox.com/s/kossq3e9k10jvj...nk.ts?dl=0

The same again at 22.39 on the same channel.

Edit: Added logs zip ...