Failed to record (1 Viewer)

[J-B-N]

MediaPortal Version: 1.1.1 final
MediaPortal Skin: StreamedMP
Windows Version: Window 7 64-bit
CPU Type: Athlon64 3700+
HDD: Samsung SP2504C 250Gb
Memory: 2 * DDR2 1GB PC6400
Motherboard: Asus M3A78-T
Video Card: onboard Raedon HD 3300
Video Card Driver: ATI 10.4
Sound Card: Onboard
Sound Card AC3:
Sound Card Driver: Realtek
1. TV Card: TERRATEC Cinergy 2400i DT
1. TV Card Type: DVB-T
1. TV Card Driver: 1.0.3.255
2. TV Card: FireDTV
2. TV Card Type: DVB-T
2. TV Card Driver: 4.7
3. TV Card:
3. TV Card Type:
3. TV Card Driver:
4. TV Card:
4. TV Card Type:
4. TV Card Driver:
MPEG2 Video Codec: ffdshow
MPEG2 Audio Codec: SAF 5.0
h.264 Video Codec: SAF 5.0
Satelite/CableTV Provider: Boxer Sweden
HTPC Case: Accent HT-200 (Black)
Cooling: AMD included
Power Supply: 520W Corsair CMPSU-520HXEU
Remote: MCE
TV: LG 4700
TV - HTPC Connection: HDMI


Today MP failed to record a show for me. I was watching a recording and expected a show to be recorded, it didn't. I have noticed this before but can't really understand why and can't see any obvious errors in the logs (but mind you I am not that good at reading logs). When I noticed that MP didn't record I tuned the channel and the recording started.

However I found the below logged a few times:

2010-10-17 21:08:12.555072 [scheduler thread(9)]: Scheduler: Time to record SVT1 21:08-21:55 The Event
2010-10-17 21:08:12.555072 [scheduler thread(9)]: Controller: find free card for channel SVT1
2010-10-17 21:08:12.557073 [scheduler thread(9)]: Controller:   got 1 tuning details for SVT1
2010-10-17 21:08:12.557073 [scheduler thread(9)]: Controller:   channel #1 DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8 
2010-10-17 21:08:12.563073 [scheduler thread(9)]: Controller:    card:3 type:DvbT is available priority:5 #users:0 same transponder:True
2010-10-17 21:08:12.567073 [scheduler thread(9)]: Controller:    card:4 type:DvbT is available priority:4 #users:0 same transponder:True
2010-10-17 21:08:12.574073 [scheduler thread(9)]: Controller:    card:2 type:DvbT is available priority:3 #users:0 same transponder:True
2010-10-17 21:08:12.576074 [scheduler thread(9)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2010-10-17 21:08:12.578074 [scheduler thread(9)]: Controller:    card:1 type:DvbIP cannot tune to channel
2010-10-17 21:08:12.579074 [scheduler thread(9)]: Controller: found 3 available
2010-10-17 21:08:12.579074 [scheduler thread(9)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 23 msec
2010-10-17 21:08:12.583074 [scheduler thread(9)]: Scheduler : record on free card:3 priority:5
2010-10-17 21:08:12.586074 [scheduler thread(9)]: Controller: epg stop
2010-10-17 21:08:12.587074 [scheduler thread(9)]: Scheduler : record, first tune to channel
2010-10-17 21:08:12.591074 [scheduler thread(9)]: card: Tune 3 to SVT1
2010-10-17 21:08:12.591074 [scheduler thread(9)]: card: user: scheduler373:3:-1 tune DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:08:12.598075 [scheduler thread(9)]: dvbt: Tune:DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:08:12.598075 [scheduler thread(9)]: dvb:Submiting tunerequest Channel:SVT1 subChannel:-1 
2010-10-17 21:08:12.598075 [scheduler thread(9)]: dvb:Getting new subchannel
2010-10-17 21:08:12.599075 [scheduler thread(9)]: dvb:GetNewSubChannel:0 #0
2010-10-17 21:08:12.600075 [scheduler thread(9)]: TvDvbChannel ctor new subchIndex:0
2010-10-17 21:08:12.600075 [scheduler thread(9)]: dvb:Submit tunerequest size:1 new:0
2010-10-17 21:08:12.601075 [scheduler thread(9)]: subch:0 OnBeforeTune
2010-10-17 21:08:12.601075 [scheduler thread(9)]: dvb:Submit tunerequest calling put_TuneRequest
2010-10-17 21:08:12.602075 [scheduler thread(9)]: dvb:Submit tunerequest done calling put_TuneRequest
2010-10-17 21:08:12.602075 [scheduler thread(9)]: subch:0 OnAfterTune
2010-10-17 21:08:12.602075 [scheduler thread(9)]: subch:0 OnGraphStart
2010-10-17 21:08:12.603075 [scheduler thread(9)]: dvb:  RunGraph
2010-10-17 21:08:12.609075 [scheduler thread(9)]: dvb:  RunGraph returns: 0x8000FFFF
2010-10-17 21:08:12.610076 [scheduler thread(9)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2010-10-17 21:08:12.611076 [scheduler thread(9)]: DVB subch:0 Decompose()
2010-10-17 21:08:12.612076 [scheduler thread(9)]: FreeSubChannel CA: freeing sub channel : 0
2010-10-17 21:08:12.612076 [scheduler thread(9)]: tvcard:FreeSubChannel : no subchannels present, stopping graph
2010-10-17 21:08:12.612076 [scheduler thread(9)]: dvb:StopGraph called
2010-10-17 21:08:12.613076 [scheduler thread(9)]: tvcard:FreeAllSubChannels
2010-10-17 21:08:12.613076 [scheduler thread(9)]: dvb:StopGraph filterstate already stopped, returning.
2010-10-17 21:08:12.616076 [scheduler thread(9)]: Controller: epg start

And over and over again:

2010-10-17 21:08:27.631935 [scheduler thread(9)]: Scheduler: Time to record SVT1 21:08-21:55 The Event
2010-10-17 21:08:27.632935 [scheduler thread(9)]: Controller: find free card for channel SVT1
2010-10-17 21:08:27.633935 [scheduler thread(9)]: Controller:   got 1 tuning details for SVT1
2010-10-17 21:08:27.633935 [scheduler thread(9)]: Controller:   channel #1 DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8 
2010-10-17 21:08:27.639935 [scheduler thread(9)]: Controller:    card:3 type:DvbT is available priority:5 #users:0 same transponder:True
2010-10-17 21:08:27.644936 [scheduler thread(9)]: Controller:    card:4 type:DvbT is available priority:4 #users:0 same transponder:True
2010-10-17 21:08:27.646936 [scheduler thread(9)]: Controller:    card:2 type:DvbT is available priority:3 #users:0 same transponder:True
2010-10-17 21:08:27.648936 [scheduler thread(9)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2010-10-17 21:08:27.650936 [scheduler thread(9)]: Controller:    card:1 type:DvbIP cannot tune to channel
2010-10-17 21:08:27.650936 [scheduler thread(9)]: Controller: found 3 available
2010-10-17 21:08:27.651936 [scheduler thread(9)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 18 msec
2010-10-17 21:08:27.651936 [scheduler thread(9)]: Scheduler : record on free card:3 priority:5
2010-10-17 21:08:27.652936 [scheduler thread(9)]: Controller: epg stop
2010-10-17 21:08:27.653936 [scheduler thread(9)]: Scheduler : record, first tune to channel
2010-10-17 21:08:27.653936 [scheduler thread(9)]: card: Tune 3 to SVT1
2010-10-17 21:08:27.653936 [scheduler thread(9)]: card: user: scheduler373:3:-1 tune DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:08:27.662937 [scheduler thread(9)]: dvbt: Tune:DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:08:27.662937 [scheduler thread(9)]: dvb:Submiting tunerequest Channel:SVT1 subChannel:-1 
2010-10-17 21:08:27.662937 [scheduler thread(9)]: dvb:Getting new subchannel
2010-10-17 21:08:27.663937 [scheduler thread(9)]: dvb:GetNewSubChannel:0 #0
2010-10-17 21:08:27.664937 [scheduler thread(9)]: TvDvbChannel ctor new subchIndex:0
2010-10-17 21:08:27.664937 [scheduler thread(9)]: dvb:Submit tunerequest size:1 new:0
2010-10-17 21:08:27.664937 [scheduler thread(9)]: subch:0 OnBeforeTune
2010-10-17 21:08:27.665937 [scheduler thread(9)]: dvb:Submit tunerequest calling put_TuneRequest
2010-10-17 21:08:27.665937 [scheduler thread(9)]: dvb:Submit tunerequest done calling put_TuneRequest
2010-10-17 21:08:27.666937 [scheduler thread(9)]: subch:0 OnAfterTune
2010-10-17 21:08:27.666937 [scheduler thread(9)]: subch:0 OnGraphStart
2010-10-17 21:08:27.666937 [scheduler thread(9)]: dvb:  RunGraph
2010-10-17 21:08:27.672937 [scheduler thread(9)]: dvb:  RunGraph returns: 0x8000FFFF
2010-10-17 21:08:27.673937 [scheduler thread(9)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2010-10-17 21:08:27.673937 [scheduler thread(9)]: DVB subch:0 Decompose()
2010-10-17 21:08:27.675937 [scheduler thread(9)]: FreeSubChannel CA: freeing sub channel : 0
2010-10-17 21:08:27.677937 [scheduler thread(9)]: tvcard:FreeSubChannel : no subchannels present, stopping graph
2010-10-17 21:08:27.677937 [scheduler thread(9)]: dvb:StopGraph called
2010-10-17 21:08:27.678937 [scheduler thread(9)]: tvcard:FreeAllSubChannels
2010-10-17 21:08:27.678937 [scheduler thread(9)]: dvb:StopGraph filterstate already stopped, returning.
2010-10-17 21:08:27.681938 [scheduler thread(9)]: Controller: epg start

So the above errors indicate that MPsomehow can't tune the channel?

When I tuned the channel the below is logged:

2010-10-17 21:34:46.484240 [(19)]: card2:Nejdeby-Dator 3 -1
2010-10-17 21:34:46.484240 [(19)]: Controller: Nejdeby-Dator 3 -1
2010-10-17 21:34:46.485240 [(19)]: Controller: Timeshifting failed, lets try next available card.
2010-10-17 21:34:46.487240 [(19)]: card: CardTune 4 SVT1 Nejdeby-Dator:4:-1
2010-10-17 21:34:46.487240 [(19)]: card: Tune 4 to SVT1
2010-10-17 21:34:46.487240 [(19)]: card: user: Nejdeby-Dator:4:-1 tune DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:34:46.493240 [(19)]: dvbt: Tune:DVBT:tv:Sveriges Television SVT1 Freq:522000 ONID:8945 TSID:1021 SID:5840 PMT:0x16D0 FTA:True LCN:1 BandWidth:8
2010-10-17 21:34:46.493240 [(19)]: dvb:Submiting tunerequest Channel:SVT1 subChannel:-1 
2010-10-17 21:34:46.494241 [(19)]: dvb:Getting new subchannel
2010-10-17 21:34:46.494241 [(19)]: dvb:GetNewSubChannel:0 #0
2010-10-17 21:34:46.495241 [(19)]: TvDvbChannel ctor new subchIndex:0
2010-10-17 21:34:46.495241 [(19)]: dvb:Submit tunerequest size:1 new:0

I noticed there is an error logged in tvserver_error, an exception from "start graph".

This also indicates that the first tuning attemt failed? And the second, on a new card worked?

So then the bug might be in the routine to try to start recordings, it doesn't itterate over the available cards when it fails?

 

[jameson_uk]

I noticed there is an error logged in tvserver_error, an exception from "start graph".

This normally means that one of your cards is not working when the machine resumes from standby.
I did notice that your IP address in an internet one? Is you machine connected directly to the internet not via a router?

This also indicates that the first tuning attemt failed? And the second, on a new card worked?

So then the bug might be in the routine to try to start recordings, it doesn't itterate over the available cards when it fails?

This is by design but a new feature to allow this is being added for 1.2 (0003067: scheduler - try next card incase of failure. - MediaPortal Bugtracker)

That said you will still probably have the problem just that recordings should work. I can't figure out which cards map to which of your physical cards but remember that priorities for live TV and recorded TV work the other way around. I think card 2 is your FireDTV card with CAM leaving cards 3 and 4 as your Cinergy 2400i.

So it looks like your FireDTV card is set to me used for live TV by default and the Cinergy 2400i for recordings. This would also suggest that it is the Cinergy 2400i that is not working on resume. It may be worth trying the re-initialise service on resume to see if that helps.

So unfortunately it looks like this is an issue with the hardware / drivers not MP.

 

[J-B-N]

Thanks for the reply. I then guess my problems are related to resuming.

My HTPC is connected over wifi to my dsl-router but it seem to provide a real IPv4 adress. I will try to use the loopback interface instead…

My plan has always been to use my Cinergy tuners for the FTA channels, like SVT1. So I do an unsymmetrical channel allocation, ie only FTA channels on the Cinergy and all channels on my FireDTV. This is actually on of my key points for using MP over other solutions out there.

The new feature in 1.2.0 would likely have solved my problem in this case. So I am very grateful for this addition for any problems in the future.

Anyhow, thanks for the help!