"failed because recording service not running" but records OK?

[Streams]

Installed the latest beta version and this still appears to be a problem. Some recordings fail to go from pending to ready. When i restart the recording service, they go to ready, but say : "failed because recording service not running"

[pcostanza]

This has been reported by a few others. I'm sure sub will be looking into it and working on a fix.

[elbryyan]

I just want to add that I've seen this issue on my new 1.5.36 build. I disregarded it the first time I saw it as a possible set up issue as it was on a recording for the same day that I was making the change over to NPVR but I've now seen it on a few other recordings. They have so far been on recordings in the wee hours of the morning, ie I have the news scheduled to record at 10pm and it also replays at 2 am so have not affected the WAF yet. I will try to capture any logs if I notice it again.

Also, I've seen one time this week as well when I was checking that things were recording an episode not showing up as red in the guide and so rescheduling it and having multiple instances being recorded. This happened this week for Chuck, it actually recorded the same show 3 times as even the second time I scheduled it the guide did not turn red. The same episode showed up 3 times in ready after it finished as well.

[sub]

Post the logs, along with the name/time of the recording, and I'll look into it.

[elbryyan]

Here are my latest logs from this morning. I'm not sure how far back it goes but checking the whats new recordings this morning the error seems to be happening about the same time and on the same two channels the last couple of days. These two recordings seem to have failed with the error over the last few days, I noticed some back to the 17th but don't know if the logs will show them. Thanks Sub.

1. Clifford
1-19-11 11am KUHT-HD
2. Sesame Street
1-19-11 9am KUHT-HD
3. Pokerstars.net Big Game
1-20-11 1am KRIVDT

[ATTACHMENT NOT FOUND]

[Reddwarf]

I'v had this happening now and then since version .28 (I think). I'v looked in the logs but nothing abnormal to be seen, the recording service is clearly running since other recordings that overlap in time records ok.

[elbryyan]

I just wanted to bump this as it has fallen a few pages. It's happened a few more times on my pokerstars recording but not for the kids shows. Its weird too as it shows two available recordings for the same time and day with one failed with the recording service error and the other plays fine. Maybe it could have something to do with one of my tuners. I can post more logs if you want to look some more into it sub. Thanks.

[macgyver]

Its weird too as it shows two available recordings for the same time and day with one failed with the recording service error and the other plays fine.

I have seen this a couple of times recently and while I can't be certain I think what I may have done is do a 'quick record' from the guide and then immediately changed my mind and cancelled it and then set a season record for the same program. I thought maybe the cancelled one was showing as failed and the season pass one was OK. I'll try it again and see if I can reproduce it.

[elbryyan]

I just dawned on me that the one recording ends during the EPG update at 2am. I'm going to change the hour that happens and see if that will resolve that one. Its been consistant with that one recording but I have not seen it for any others since I posted the logs.

[johnsonx42]

It doesn't help any more to change the EPG update hour, at least not on my system. I have the EPG update hour set to 4am (and it does run at 4am), and both of my shows that record from 2am to 3am get duplicated, and then the duplicate gets marked Failed. On 1.5.33 and prior, the show actually had to be recording when the EPG update started in order to be duplicated, now on 1.5.36 it's any show that records anywhere near the EPG update time. I suspect it actually has more to do with that time NPVR considers to be "past" vs "future". I kept meaning to report this new behaviour, but it's one of those things that doesn't really bother me any more...
Here's the relevant bits from my NRecord.log:
First, the two 2am shows starting and finishing recording:

Code:

2011-01-25 02:00:01.218    [DEBUG][7]    Started recording (48696:F:\Recordings\The PokerStars.net Big Game\The PokerStars.net Big Game_20110125_02000300.ts)
2011-01-25 02:05:04.421    [DEBUG][7]    Started recording (48758:F:\Recordings\Poker After Dark\Poker After Dark_20110125_02050304.ts)
.....
2011-01-25 03:00:00.062    [DEBUG][7]    Stopping recording (48696). Past end time of recording.
2011-01-25 03:04:00.157    [DEBUG][7]    Stopping recording (48758). Past end time of recording.

Now the EPG update at 4am matches and schedules the same two recordings again, even though both already ended an hour ago:

Code:

2011-01-25 04:02:09.664    [INFO][8]    UpdateRecurringRecording(53, 'The PokerStars.net Big Game'):
<Rules><EPGTitle>The PokerStars.net Big Game</EPGTitle><ChannelOID>6939</ChannelOID><ChannelName>KTTV DT</ChannelName><StartTime>2010-06-29T09:00:00.0000000Z</StartTime><EndTime>2010-06-29T10:00:00.0000000Z</EndTime><PrePadding>0</PrePadding><PostPadding>0</PostPadding><Quality>0</Quality><Keep>4</Keep></Rules>
2011-01-25 04:02:09.695    [DEBUG][8]    LoadListingsMatchingTitle(channel=6939,title=The PokerStars.net Big Game)
2011-01-25 04:02:09.695    [DEBUG][8]     - Potential episode at: 1/25/2011 2:00:00 AM
2011-01-25 04:02:09.695    [DEBUG][8]       ...check IsValid()
2011-01-25 04:02:09.695    [DEBUG][8]       ...scheduling episode
......
2011-01-25 04:02:16.211    [INFO][8]    UpdateRecurringRecording(75, 'Poker After Dark'):
<Rules>
  <EPGTitle>Poker After Dark</EPGTitle>
  <ChannelOID>6947</ChannelOID>
  <ChannelName>NBC-4LA</ChannelName>
  <StartTime>2010-09-07T09:05:00.0000000Z</StartTime>
  <EndTime>2010-09-07T10:04:00.0000000Z</EndTime>
  <PrePadding>0</PrePadding>
  <PostPadding>0</PostPadding>
  <Quality>0</Quality>
  <Keep>3</Keep>
</Rules>

2011-01-25 04:02:16.242    [DEBUG][8]    LoadListingsMatchingTitle(channel=6947,title=Poker After Dark)
2011-01-25 04:02:16.242    [DEBUG][8]     - Potential episode at: 1/25/2011 2:05:00 AM
2011-01-25 04:02:16.242    [DEBUG][8]       ...check IsValid()
2011-01-25 04:02:16.242    [DEBUG][8]       ...scheduling episode

and then finally it reloads the recording schedule, and then marks the duplicates failed:

Code:

2011-01-25 04:02:24.820    [DEBUG][7]    Reloading recording schedule
2011-01-25 04:02:24.828    [DEBUG][7]    Requesting wake up for 'RecordingOID48822' at 1/25/2011 1:58 AM
2011-01-25 04:02:24.828    [DEBUG][7]    Requesting wake up for 'RecordingOID48881' at 1/25/2011 2:03 AM
....
2011-01-25 04:02:24.836    [DEBUG][7]    Marking recording (48822) as 'Recording service not running at recording time'
2011-01-25 04:02:24.938    [DEBUG][7]    Marking recording (48881) as 'Recording service not running at recording time'