recording in progress during epg update causes problems

[johnsonx42]

I've discovered one of the ways recordings can get marked "Failed - Recording service not running at recording time".

I have a recording of a kids' show at 3:00am, the same time as the EPG update (only XMLTV, no dvb epg). I've discovered for 2 nights in a row that the recording in progress during the update gets duplicated, and then it and all subsequent recordings get marked "Failed - Recording service not running at recording time".

It appears also that after the EPG update, the recording service gets into a bit of a confused state. It no longer updates it's recording wakeup schedule, until some event occurs to wake it up. On 7-11, I restarted the recording service which caused it to reload the schedule. On 7-12 at 8:00am I simply deleted an old recording, which caused it to wake up.

The attached NRecord7-11.log.zip has the logs pertaining to the 7-11 occurance. The order of the log files is a little funny because I had to recover some from windows' "Previous Versions" facility. Then the attached NRecord7-12.log.zip shows this morning's occurrance.

Of interest is this line from the NRecord.log.2 file in the 7-12 zip:

Code:

2010-07-11 13:17:12.750    [DEBUG][6]    Requesting wake up for 'RecordingOID1272' at 7/12/2010 2:58 AM

So recording 1272 is set for 3:00am on 7-12.
Then this morning, in the NRecord.log:

Code:

2010-07-12 03:30:00.195    [DEBUG][6]    Stopping recording (1272). Past end time of recording.

Good, recording 1272 stopped on time, all is well... but then after I deleted an old recording to "kick" the recording service:

Code:

2010-07-12 08:00:43.695    [DEBUG][6]    Requesting wake up for 'RecordingOID1354' at 7/12/2010 2:58 AM
.....
2010-07-12 08:00:43.708    [DEBUG][6]    Marking recording (1354) as 'Recording service not running at recording time'

Recording 1354? Where did that come from? It's a duplicate of recording 1272 that didn't exist before the EPG update. Yes, the 3:00am Zula Patrol recording shows up twice in "What's New": one successful, one failed.

Things went the same way on 7-11, except two other recordings occurred but were marked "failed" before I restarted the recording service.

Enjoy!

[johnsonx42]

a further comment - I think this also explains why I didn't have this problem for quite awhile, until the 1.5.24 update: the automatic EPG update usually didn't work, so after the epg update I had no recordings scheduled at all. Then when I would manually update the EPG, everything would re-schedule just fine.

[johnsonx42]

one last comment:

My observation is there are or were 3 conditions that could erroneously produce successful recordings marked "Failed - Recording Service not running at recording time"

1. The scenario I described in this thread - EPG update with recording in progress.

2. A bug in the padding logic, which would cause a recording to be marked failed at the moment it was supposed to end without padding, even though it would finish fine a few minutes later with padding. I think this one is probably fixed now, but I just don't use padding so I haven't seen it since a couple of recordings I set with padding by mistake. (edit: actually I'm not even sure about this one... I had a couple of such recordings with padding where the log SAID they were being marked failed, yet they showed up fine in the Recordings lists)

3. Having two instances of NextPVR.exe running. This was never proved for sure, but I went along time without seeing the problem after I took steps to ensure I wouldn't have two instances running. I definitely did have two running the first time I had this problem, and it was not after an EPG update with a recording in progress.

later edit: ignore this whole post. #1 isn't even accurate, it's got nothing to do with a recording in progress. #2 I'm very unsure of. #3 I now think was a red herring. move along.

[johnsonx42]

interesting, I deleted the 3:00am recording scheduled for this morning, but the recording service still has not reloaded the recording schedule; there's nothing at all in the nrecord.log after the epg update completed. therefore I strongly suspect the recording scheduled for 11:00am will be marked "Failed - recording service not running...". I'll report back later, off to work for now.

[johnsonx42]

ok, so part of the premise of my thread is wrong. having the EPG update during a recording-in-progress doesn't actually cause the problem at all - rather it just happens to be what pointed me towards the problem. It does appear though that a recording in progress during the EPG update will need some special treatment.

The problem is simply that NRecord doesn't update the recording schedule after the automatic EPG update. It goes on making recordings using the old Recording ID's, but the scheduler is looking for recordings to complete with the new ID's so it continues to show them as Pending even though they've already completed. When something finally happens to cause it to reload the recording schedule (delete a recording, restart the recording service, schedule a new recording, probably other conditions), it suddenly sees the recordings with the new ID's, sees they never completed, and marks them all as "Failed - Recording service not running at recording time".

The attached log shows the recording service being started today just before 3:30pm (the computer crashed while watching a NetFlix movie with whurlston's new plugin). It loads the new recording schedule, marks several as "Failed - Recording service not running..." and starts recording the last minute of a show that had started recording at 3:00pm on the old schedule. I don't have the NRecord.log from earlier in the day showing the recordings being completed using the old Recording ID's due to the logging bug I mentioned in another thread, but it's all the same as the logs I already posted from the 11th and 12th.

[sub]

Dont worry - I'm not ignoring you. I've got this thread marked in my to-do list. Just having a few busy days with day job stuff at the moment.

[johnsonx42]

I figured as much, no worries. Ironically the problem is somewhat self-correcting for us now, as we've been using whulston's new netflix plugin quite a bit and it tends to crash the computer every few hours (I blame Silverlight or the video drivers more than the plugin), so the recording schedule gets reloaded before any real damage is done

Mostly I kept posting because typing it out helps me understand the problem better myself. I actually now think the whole "multiple instances of NextPVR.exe" thing was a red herring all along, at least where this issue is concerned.

[Reddwarf]

The problem is simply that NRecord doesn't update the recording schedule after the automatic EPG update. It goes on making recordings using the old Recording ID's, but the scheduler is looking for recordings to complete with the new ID's so it continues to show them as Pending even though they've already completed. When something finally happens to cause it to reload the recording schedule (delete a recording, restart the recording service, schedule a new recording, probably other conditions), it suddenly sees the recordings with the new ID's, sees they never completed, and marks them all as "Failed - Recording service not running at recording time".

That makes sense, it also explaing why I have bees seeing recordings as pending even long after they'v finished (looking at Status->Pending in Ntray).

So it would be healty for the system to restart the recording servive every morning after the auto epgupdate?

[imilne]

That makes sense, it also explaing why I have bees seeing recordings as pending even long after they'v finished (looking at Status->Pending in Ntray).

So it would be healty for the system to restart the recording servive every morning after the auto epgupdate?

There may be more to it than that too. Because I've been trying to get the System plugin to monitor active and pending recordings I've been watching what the tray says a lot. I've found if you start a recording ("now") then cancel it soon afterwards, it stays listed as pending (but not recording) for a long while afterwards. Because my plugin is always looking for the earliest pending recording, it ends up showing ones with a negative start time.

Iain

[Reddwarf]

There may be more to it than that too. Because I've been trying to get the System plugin to monitor active and pending recordings I've been watching what the tray says a lot. I've found if you start a recording ("now") then cancel it soon afterwards, it stays listed as pending (but not recording) for a long while afterwards. Because my plugin is always looking for the earliest pending recording, it ends up showing ones with a negative start time.

Iain

Do you also get double recordings? I get a lot of recordings (recurring) with two identical entries in the "Ready Recordings" but one of them is marked as Failed. I checked that they are only scheduled once in "Pending".