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?