HDPVR errors

[mvallevand]

I just started trying to get me wife more involved with NextPVR and so far it is an epic failure since NRecord is marking recordings on her show as failed I have several examples that have a similar pattern.

Code:

2013-10-31 11:00:04.220    [DEBUG][8]    About to tune graph to:
...
2013-10-31 11:00:04.530    [DEBUG][8]    device confirms bitrate as: 16000000
2013-10-31 11:00:06.547    [DEBUG][8]    Removing filter  NPVR Writer2
2013-10-31 11:00:06.547    [DEBUG][8]    Removing filter  NPVR Writer
2013-10-31 11:00:06.547    [DEBUG][8]    Removing filter  Infinite Pin Tee Filter
2013-10-31 11:00:06.548    [DEBUG][8]    Removing filter  Hauppauge HD PVR Encoder
2013-10-31 11:00:06.549    [DEBUG][8]    Removing filter  Hauppauge HD PVR Capture Device
2013-10-31 11:00:06.550    [DEBUG][8]    Removing filter  Hauppauge HD PVR Crossbar
2013-10-31 11:00:06.551    [DEBUG][8]    Temp at 31/10/2013 11:00:16 AM
2013-10-31 11:00:06.551    [DEBUG][8]    Failed to start recording on allocated device (3782:K:\The View\The View_20131031_11001200.ts): 'Device failed to start'
2013-10-31 11:00:06.551    [DEBUG][8]    Looking for second chance device to perform recording...
2013-10-31 11:00:06.557    [DEBUG][8]    Temp at 31/10/2013 11:00:16 AM
2013-10-31 11:00:06.557    [DEBUG][8]    Failed to start recording (3782:K:\The View\The View_20131031_11001200.ts): 'Device failed to start'

But the file exists
31/10/2013  11:56          79,667  The View_20131031_11001200.ts.Timing.Info
31/10/2013  11:56   3,847,520,124  The View_20131031_11001200.ts

and the Timing.Info is ok
3588350,3846766460

It is possible even likely it that this is caused by me forgetting to turn of the Full TS write and the failure is not on the file itself but on the full file not being written. I want to give it another shoot tomorrow but after two days like this she is less than impressed so sub do you think this is related to FullTS?

Martin

[sub]

Was the recording on the HDPVR, or a digital device? The RecordFullTS registry setting only applies to digital devices. Leave it on can full your hard disk very quickly.

Can you supply a longer snippet of the log, or the complete log?

[mvallevand]

Sure. It was an HDPVR I don't use the digital tuners for recording much since I changed the setting for the issue last week.

Martin

[sub]

I can't see an obvious reason, but it looks like even the very first attempt to use the device failed (followed by several following attempts). Are you sure the device wasn't being used elsewhere? I haven't seen any other comments indicating this is a problem.

It started working late in the logs. Maybe it'd been unplugged, and plugged back in, or something like that?

[mvallevand]

I can't see an obvious reason, but it looks like even the very first attempt to use the device failed (followed by several following attempts). Are you sure the device wasn't being used elsewhere? I haven't seen any other comments indicating this is a problem.

It started working late in the logs. Maybe it'd been unplugged, and plugged back in, or something like that?

It did work both days when I come to test when I came home (of course).

It is not being used elsewhere and as I wrote the recording are there.

Martin

[sub]

This patch wont fix anything, but it will log errors starting the graph etc, which wasn't being done previously. It might give us some more ideas.

[mvallevand]

Ok. I noticed something else, it's almost like there are ghost recordings, both of today's shows showed up going to postprocessing.bat with an OID that is not in the database

Code:

[...startup]
2013-10-31 12:00:03.959    [DEBUG][1]    imageGrabLite, Version=2.2.5037.36382, Culture=neutral, PublicKeyToken=null
2013-10-31 12:00:03.977    [DEBUG][1]    Command Line --oid 3761 --zap2it --rename --first --live
2013-10-31 12:00:04.022    [DEBUG][1]    Rename file True
2013-10-31 12:00:04.182    [DEBUG][1]    Searching select scheduled_recording.name, event_details, start_time, filename from scheduled_recording, channel where scheduled_recording.oid = 3761 and scheduled_recording.channel_oid = channel.oid and channel.number not in (54, 56)
2013-10-31 12:00:04.198    [DEBUG][1]    No matches found
2013-10-31 12:00:04.200    [DEBUG][1]    c:\temp\
2013-10-31 12:00:04.203    [ERROR][1]    Read Error Object reference not set to an instance of an object.

Code:

2013-10-31 14:00:04.049    [DEBUG][1]    imageGrabLite, Version=2.2.5037.36382, Culture=neutral, PublicKeyToken=null
2013-10-31 14:00:04.066    [DEBUG][1]    Command Line --oid 3772 --zap2it --rename --first --live
2013-10-31 14:00:04.105    [DEBUG][1]    Rename file True
2013-10-31 14:00:04.242    [DEBUG][1]    Searching select scheduled_recording.name, event_details, start_time, filename from scheduled_recording, channel where scheduled_recording.oid = 3772 and scheduled_recording.channel_oid = channel.oid and channel.number not in (54, 56)
2013-10-31 14:00:04.258    [DEBUG][1]    No matches found
2013-10-31 14:00:04.260    [DEBUG][1]    c:\temp\
2013-10-31 14:00:04.263    [ERROR][1]    Read Error Object reference not set to an instance of an object.

I attached the preceding NRecord but those OID don't exist in either set of logs going back 4 days. My npvr.db3 passes integrity checks too.

Martin

[mvallevand]

Here are the new logs after the patch. A couple of things

1) First NRecord failed to update the database after the EPG update with the record locked error (NRecord.log.1) so I restarted it.

2) The View shows as failed in the NRecord.log even with the new logging but it actually recorded and Post Processing was performed (not shown in logs)and the database is status 2 not 3

3) The Bold & the Beautiful shows as recorded but the tuning didn't work, it was the wrong channel (not channel 20 from above) either.

Martin

[sub]

1) First NRecord failed to update the database after the EPG update with the record locked error (NRecord.log.1) so I restarted it.

Keeping an eye out for this one. There is that other thread where a few people have said they've got a database lock error.

Yours seems to have happened immediately after an EPG update. Will need to see if others are the same.

2) The View shows as failed in the NRecord.log even with the new logging but it actually recorded and Post Processing was performed (not shown in logs)and the database is status 2 not 3

What message red message did it show in the Recordings screen?

3) The Bold & the Beautiful shows as recorded but the tuning didn't work, it was the wrong channel (not channel 20 from above) either.

It looks like it successfully ran the blaster. Are these not the parameters you'd expect for this channel?

Code:

2013-11-01 13:30:07.009    [INFO][8]    Running blaster: C:\Program Files\Timmmoore\MCE 2005 STB Controller\channel.exe -f -a0 2 0013

[mvallevand]

What message red message did it show in the Recordings screen?

Nothing at all, everything about the recording was fine.

It looks like it successfully ran the blaster. Are these not the parameters you'd expect for this channel?

Code:

2013-11-01 13:30:07.009    [INFO][8]    Running blaster: C:\Program Files\Timmmoore\MCE 2005 STB Controller\channel.exe -f -a0 2 0013

It is what I'd expect but it was on channel 3 not 13. I have tried several times tonight as live tv and it always tunes 13

Martin