1.4.7 Failed recordings.

[psycik]

Been getting this happening every so often, maybe once a week, where i'll get on the system and see that all the recordings have failed.

Log looks like this:

Code:

2009-11-04 08:01:27.750 VERBOSE [5] pending: (8497) ONE Sport: Red Bull Air Race 08/11/2009 1:00 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking MasterChef Australia 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8496) MasterChef Australia 08/11/2009 5:25 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Wipeout 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8488) Wipeout 08/11/2009 7:30 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Sunday 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8501) Sunday 08/11/2009 7:30 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking NCIS 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8484) NCIS 08/11/2009 8:30 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Sunday Theatre: The Tudors 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8502) Sunday Theatre: The Tudors 08/11/2009 8:30 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking CSI: Miami 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8481) CSI: Miami 08/11/2009 9:30 p.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Seinfeld 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8493) Seinfeld 09/11/2009 3:30 a.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Seinfeld 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8494) Seinfeld 09/11/2009 4:00 a.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Seinfeld 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8491) Seinfeld 09/11/2009 10:00 a.m. 2009-11-04 08:01:27.750 VERBOSE [5] - checking Seinfeld 2009-11-04 08:01:27.750 VERBOSE [5] pending: (8492) Seinfeld 09/11/2009 10:30 a.m. 2009-11-04 08:01:28.031 VERBOSE [5] Found new Pending recording needed wakeup request: Seinfeld (04/11/2009 10:00:00) 2009-11-04 08:01:28.031 VERBOSE [5] Found new Pending recording needed wakeup request: Seinfeld (04/11/2009 10:30:00) 2009-11-04 08:29:31.578 VERBOSE [14] Hour is currently 8. Conversions will happen between 1:00 and 6:00 2009-11-04 09:00:31.578 VERBOSE [14] Hour is currently 9. Conversions will happen between 1:00 and 6:00 2009-11-04 09:31:31.578 VERBOSE [14] Hour is currently 9. Conversions will happen between 1:00 and 6:00 2009-11-04 09:55:00.031 INFO [5] Found new programme requiring recording: Seinfeld (8509) 2009-11-04 09:55:00.031 VERBOSE [5] Changing to channel (GBPVR.Backend.Common.USBUIRTTunerController): 10 2009-11-04 09:55:00.031 VERBOSE [5] Changing channels with USB-UIRT 2009-11-04 09:55:00.031 VERBOSE [5] Sending: 0 2009-11-04 10:02:31.578 VERBOSE [14] Hour is currently 10. Conversions will happen between 1:00 and 6:00 2009-11-04 10:33:31.578 VERBOSE [14] Hour is currently 10. Conversions will happen between 1:00 and 6:00 2009-11-04 11:04:31.578 VERBOSE [14] Hour is currently 11. Conversions will happen between 1:00 and 6:00 2009-11-04 11:35:31.578 VERBOSE [14] Hour is currently 11. Conversions will happen between 1:00 and 6:00 2009-11-04 12:06:31.578 VERBOSE [14] Hour is currently 12. Conversions will happen between 1:00 and 6:00 2009-11-04 12:37:31.578 VERBOSE [14] Hour is currently 12. Conversions will happen between 1:00 and 6:00 2009-11-04 13:08:31.578 VERBOSE [14] Hour is currently 13. Conversions will happen between 1:00 and 6:00 2009-11-04 13:39:31.578 VERBOSE [14] Hour is currently 13. Conversions will happen between 1:00 and 6:00 2009-11-04 14:10:31.578 VERBOSE [14] Hour is currently 14. Conversions will happen between 1:00 and 6:00 2009-11-04 14:41:31.578 VERBOSE [14] Hour is currently 14. Conversions will happen between 1:00 and 6:00 2009-11-04 15:12:31.578 VERBOSE [14] Hour is currently 15. Conversions will happen between 1:00 and 6:00 2009-11-04 15:43:31.578 VERBOSE [14] Hour is currently 15. Conversions will happen between 1:00 and 6:00 2009-11-04 16:14:31.578 VERBOSE [14] Hour is currently 16. Conversions will happen between 1:00 and 6:00 2009-11-04 16:45:31.578 VERBOSE [14] Hour is currently 16. Conversions will happen between 1:00 and 6:00 2009-11-04 17:16:31.578 VERBOSE [14] Hour is currently 17. Conversions will happen between 1:00 and 6:00 2009-11-04 17:47:31.578 VERBOSE [14] Hour is currently 17. Conversions will happen between 1:00 and 6:00 2009-11-04 18:18:31.578 VERBOSE [14] Hour is currently 18. Conversions will happen between 1:00 and 6:00 2009-11-04 18:49:31.578 VERBOSE [14] Hour is currently 18. Conversions will happen between 1:00 and 6:00 2009-11-04 19:20:31.578 VERBOSE [14] Hour is currently 19. Conversions will happen between 1:00 and 6:00 2009-11-04 19:51:31.578 VERBOSE [14] Hour is currently 19. Conversions will happen between 1:00 and 6:00 2009-11-04 20:22:31.578 VERBOSE [14] Hour is currently 20. Conversions will happen between 1:00 and 6:00 2009-11-04 20:53:31.578 VERBOSE [14] Hour is currently 20. Conversions will happen between 1:00 and 6:00 2009-11-04 21:17:14.453 VERBOSE [5] Sending: 1 2009-11-04 21:17:15.265 VERBOSE [5] Sending: 0 2009-11-04 21:17:24.500 VERBOSE [5] Requesting IRecordingSource to start recording: G:\Recordings\Seinfeld\Seinfeld_20091104_10001030.mpg 2009-11-04 21:17:24.500 VERBOSE [5] start recording @1 2009-11-04 21:17:24.500 VERBOSE [5] start recording @2 2009-11-04 21:17:24.500 VERBOSE [5] DirectRecordingSource about to start recording oid:11 channel:10 2009-11-04 21:17:26.125 VERBOSE [5] recording started 2009-11-04 21:17:26.125 VERBOSE [5] start recording @3 2009-11-04 21:17:26.125 VERBOSE [5] start recording @4 2009-11-04 21:17:26.125 VERBOSE [5] Programme is now recording 2009-11-04 21:17:26.125 VERBOSE [5] RecordingFactory.save() 2009-11-04 21:17:26.203 VERBOSE [5] Save(): Updated existing scheduled recording 2009-11-04 21:17:26.203 VERBOSE [5] Adding G:\Recordings\Seinfeld\Seinfeld_20091104_10001030.mpg to parallel processing queue 2009-11-04 21:17:26.203 VERBOSE [5] RecordingFactory.getExtrasForGroup(456) 2009-11-04 21:17:26.203 VERBOSE [5] ScheduledRecording is configured to keep a maximum of 6 file(s). Checking if we have too many... 2009-11-04 21:17:26.203 VERBOSE [5] RecordingFactory.loadSchedule() 2009-11-04 21:17:26.218 VERBOSE [5] - deleting extra recording from: 30/10/2009 10:10:00 2009-11-04 21:17:26.218 VERBOSE [5] RecordingFactor.DeleteSheduledRecording() 2009-11-04 21:17:26.250 VERBOSE [5] Removing additional file: G:\Recordings\Seinfeld\Seinfeld_20091030_10101040.mpg 2009-11-04 21:17:26.671 VERBOSE [5] getValue cached value: /settings/DeleteAdditionalExtensions : jpg,srt,txt,log,d2a,edl,csv,bat,wme,vprj,logo.txt,dvbsub,smi,mkv,ts 2009-11-04 21:17:26.671 VERBOSE [5] getValue cached value: /settings/AutoCreateFolders : true 2009-11-04 21:17:26.671 VERBOSE [5] getValue cached value: /settings/LiveTVDirectory : G:\Cache

There should have been recordings at about 5:30 pm and 7:30 pm, but you can see there's nothing until 21:17 or so when i start up pvrx2 and then it figures out they've all failed. There's not much to go on here, but is there anything I can check to make sure the recording service is working? As it looks like the service stays up.

The native log doesn't have much in it either:

Code:

2009-11-03 21:25:04.656 VERBOSE ConexantRecorder::StartRecording() done 2009-11-03 22:05:00.031 VERBOSE ConexantRecorder::StopRecording() 2009-11-03 22:05:00.203 VERBOSE ConexantRecorder::Done() 2009-11-04 08:01:27.281 VERBOSE Asking Windows to be awake for EPG update at 2009-11-5 7:58:30 (UTC 2009-11-4 18:58:30) 2009-11-04 08:01:28.031 VERBOSE Asking Windows to be awake for recording (oid: 8509) at 2009-11-4 9:52:30 (UTC 2009-11-3 20:52:30) 2009-11-04 08:01:28.031 VERBOSE Asking Windows to be awake for recording (oid: 8510) at 2009-11-4 10:22:30 (UTC 2009-11-3 21:22:30) 2009-11-04 21:17:24.500 VERBOSE ConexantRecorder::StartRecording('Hauppauge PVR500 with FM tuner', 1, 64, 10, 0) 2009-11-04 21:17:24.500 VERBOSE target filename: G:\Recordings\Seinfeld\Seinfeld_20091104_10001030.mpg 2009-11-04 21:17:24.500 VERBOSE Capture Device is based on BlackBird architecture 2009-11-04 21:17:24.515 VERBOSE Capture Device is using Conexant (derived) drivers 2009-11-04 21:17:24.515 VERBOSE Loading filter names 2009-11-04 21:17:24.515 VERBOSE Found names: 2009-11-04 21:17:24.515 VERBOSE Hauppauge WinTV PVR PCI II Crossbar

[psycik]

I can see some pch activity happening in the morning, after that 8 am time when the recording server has given up (or stopped reporting I should say). Could that be doing something to the recording service?

Although I see the pch start up at 8:17, which is after the 8:01 mentioned in the recording service logs.

[psycik]

Any thoughts sub?

[sub]

I've had this post sitting in a tab in my browser since this morning. I was going to come back and take a look a little later in the morning when I had more time available.

[psycik]

Cool, seems a strange problem, far as I can see, recording service is still running but not responding. Not sure if the PCH is killing it, or some sort of resume from S1 power issue.

This morning I killed all power saving options.

[sub]

Are you still on XP as per your sig? I can think of a reason on Win7/Vista, but that wouldnt apply to XP.

[psycik]

Yeah still xp. SHould be fairly up to date in respect of patches.

[sub]

Ok. It sounds like the Recording Service wasnt aware of the recordings at all.

You might need to check if these recordings showed up in your pending.log.

[psycik]

they showed up afterwards (after I started pvrx2 again) as failed.

[sub]

Do you know how these specific recordings were scheduled? ie, manually from the tv guide as one-off recordings, by the system as new episodes in season recording, from EWA, or manual recordings?