TV Service dying (1 Viewer)

[mm1352000]

Cheers DJBlu

 

[hucknallred]

Hi,

If you are using 1.3.0 Alpha can you try this TSWriter and if it fails then upload the Log files.

I'm not using the Alpha, but am willing to give it a try to get to the bottom of the issue. It may be later on this week though.

 

[hucknallred]

OK, I've installed the Alpha & the TSwriter,it all seems pretty slick, yet to see any problems

 

[hucknallred]

OK, something's happened but it may be unconnected. I have 4 tuners, 2 x DVB-T2 & 2 x DVB-S2.
I had one recording running on each, when I tried another on the S card I get no tuner available, but MP stays alive. Going into server config I can see the tuner is free, but I can't timeshift or preview, as there's no card available. The T card is fine. Go to stop service & it won't, needs a manual kill.
Restart service & still no free card it says. Problems happened around 20:03, I dumped the logs after restarting TV service
It may not be connected, but maybe I had other recordings going on 1.2.3 when I had the previous problems...

 

[mm1352000]

This is something entirely different:

2012-09-20 19:59:11.130000 [(13)]: Controller: StartTimeShifting Vintage TV 962
2012-09-20 19:59:11.131000 [(13)]: Controller: epg stop
2012-09-20 19:59:11.132000 [(13)]: Controller: find free card for channel Vintage TV
2012-09-20 19:59:11.133000 [(13)]: Controller: find card for channel Vintage TV
2012-09-20 19:59:11.134000 [(13)]: Controller: got 1 tuning details for Vintage TV
2012-09-20 19:59:11.135000 [(13)]: Controller: channel #1 DVBS:tv:BSkyB Vintage TV Freq:12643000 ONID:2 TSID:2603 SID:54222 PMT:0x105 FTA:True LCN:962 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate2_3 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-09-20 19:59:11.136000 [(13)]: Controller: card:1 typevbIP is disabled
2012-09-20 19:59:11.136000 [(13)]: Controller: card:2 type:RadioWebStream is disabled
2012-09-20 19:59:11.137000 [(13)]: Controller: card:6 typevbS can tune to channel
2012-09-20 19:59:11.138000 [(13)]: Controller: card:5 typevbS can tune to channel
2012-09-20 19:59:11.139000 [(13)]: Controller: card:3 typevbT cannot tune to channel
2012-09-20 19:59:11.140000 [(13)]: Controller: card:4 typevbT cannot tune to channel
2012-09-20 19:59:11.140000 [(13)]: Controller: found 2 card(s) for channel
2012-09-20 19:59:11.141000 [(13)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 8 msec
2012-09-20 19:59:11.142000 [(13)]: Controller: found 2 free card(s)
2012-09-20 19:59:11.143000 [(13)]: AdvancedCardAllocation.GetFreeCardsForChannel took 10 msec
2012-09-20 19:59:11.149000 [(13)]: CardReservationBase.RequestCardTuneReservation: placed reservation with id=126, tuningdetails=DVBS:tv:BSkyB Vintage TV Freq:12643000 ONID:2 TSID:2603 SID:54222 PMT:0x105 FTA:True LCN:962 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate2_3 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-09-20 19:59:11.150000 [(13)]: CardReservationBase.RequestCardTuneReservation: failed reservation tuningdetails=DVBS:tv:BSkyB Vintage TV Freq:12643000 ONID:2 TSID:2603 SID:54222 PMT:0x105 FTA:True LCN:962 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate2_3 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet, res id blocking=31, state=TuneCancelled
2012-09-20 19:59:11.154000 [(13)]: Controller: card:6 typevbS users: 1
2012-09-20 19:59:11.155000 [(13)]: Controller: card:6 typevbS is not available, tuned to different transponder
2012-09-20 19:59:11.156000 [(13)]: CardReservation.CancelCardReservation id=126
2012-09-20 19:59:11.157000 [(13)]: Controller: StartTimeShifting failed:AllCardsBusy

I don't know enough about the card reservation changes in MP 1.3a to make an intelligent comment.
@gibman: is this something you've seen before?

 

[gibman]

what it says is:

res id blocking=31, state=TuneCancelled

here u can see see why the tuner reservation failed.
it's because of previous reservation with id 31 not releasing the lock. It's last known state was 'TuneCancelled'.

in order to find the culprit tune reservation in the logs, look in tv.bak file for 'CardReservationBase.RequestCardTuneReservation: placed reservation with id=31'

2012-09-18 22:58:40.433566 [DVB EPG timer(4)]: CardReservationBase.RequestCardTuneReservation: placed reservation with id=31, tuningdetails=DVBS:radio:BSkyB Kismat Freq:12523000 ONID:2 TSID:2612 SID:9566 PMT:0x141 FTA:True LCN:470 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate2_3 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet

somehow this thread stops here ??

2012-09-18 22:58:40.449166 [DVB EPG timer(4)]: dvb:GetNewSubChannel:0 #0

the next expected log line should have been:
DVB EPG timer(4)]: TvDvbChannel ctor new subchIndex:0

it essentially locks the card, preventing other tune requests to fail, and will do so until tvservice is restarted ?

.. as can be seen here:

2012-09-19 07:17:57.351966 [(26)]: CardReservationBase.RequestCardTuneReservation: placed reservation with id=34, tuningdetails=DVBS:tv:BSkyB BBC One HD Freq:10847000 ONID:2 TSID:2050 SID:6941 PMT:0x104 FTA:True LCN:32 SymbolRate:23000 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate8_9 DisEqc:None band:Universal Pilot:Off RollOff:ThirtyFive
2012-09-19 07:17:57.353966 [(26)]: CardReservationBase.HasUserHigherPriorityThanBlockingUser: True - user 'VHTPC-PC' with prio=2 vs blocking user 'epg' with prio=1
 
2012-09-19 07:17:57.354966 [(26)]: CardReservationBase.RequestCardTuneReservation: failed reservation tuningdetails=DVBS:tv:BSkyB BBC One HD Freq:10847000 ONID:2 TSID:2050 SID:6941 PMT:0x104 FTA:True LCN:32 SymbolRate:23000 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate8_9 DisEqc:None band:Universal Pilot:Off RollOff:ThirtyFive, res id blocking=31, state=TuneCancelled
 
2012-09-19 07:17:57.356966 [(26)]: CardReservationBase.RequestCardTuneReservation: placed reservation with id=35, tuningdetails=DVBT:tv: BBC One HD Freq:474000 ONID:9018 TSID:16517 SID:17540 PMT:0x19C8 FTA:True LCN:50 BandWidth:8
 
2012-09-19 07:17:57.357966 [(26)]: CardReservationBase.RequestCardTuneReservation: placed reservation with id=36, tuningdetails=DVBT:tv: BBC One HD Freq:474000 ONID:9018 TSID:16517 SID:17540 PMT:0x19C8 FTA:True LCN:50 BandWidth:8

So is it a deadlock or a bad driver ?

if a bad tuner driver decides to forever block it will cause the same symptoms.

My guess is that you can't repro this issue on demand ?

in TvDvbChannel.cs we have:

    public TvDvbChannel(IFilterGraph2 graphBuilder, ConditionalAccess ca, MDPlugs mdplugs, IBaseFilter tif,
                        IBaseFilter tsWriter, int subChannelId, IChannel channel)
    {
      _cancelled = false;
      _listenCA = false;
      _eventPMT = new ManualResetEvent(false);
      _eventCA = new ManualResetEvent(false);
      _graphState = GraphState.Created;
      _graphBuilder = graphBuilder;
      _conditionalAccess = ca;
      _mdplugs = mdplugs;
      _filterTIF = tif;
      _teletextDecoder = new DVBTeletext();
      _packetHeader = new TSHelperTools.TSHeader();
      _tsHelper = new TSHelperTools();
      _channelInfo = new ChannelInfo();
      _pmtPid = -1;
      _subChannelIndex = -1;
      _tsFilterInterface = (ITsFilter)tsWriter;
      _tsFilterInterface.AddChannel(ref _subChannelIndex);
 
      Log.Log.WriteFile("TvDvbChannel ctor new subchIndex:{0}", _subChannelIndex);
 
      _subChannelId = subChannelId;
      _conditionalAccess.AddSubChannel(_subChannelId, channel);
      _timeshiftFileName = "";
      _recordingFileName = "";
      _pmtData = null;
      _pmtLength = 0;
    }

/gibman

 

[mm1352000]

here u can see see why the tuner reservation failed.
it's because of previous reservation with id 31 not releasing the lock. It's last known state was 'TuneCancelled'.

Thanks for the explanation. Will remember this.

somehow this thread stops here ??

2012-09-18 22:58:40.449166 [DVB EPG timer(4)]: dvb:GetNewSubChannel:0 #0

the next expected log line should have been:
DVB EPG timer(4)]: TvDvbChannel ctor new subchIndex:0

it essentially locks the card, preventing other tune requests to fail, and will do so until tvservice is restarted ?

Yes, this is the famed TsWriter deadlock that we are trying to solve - the original problem in this thread.

So is it a deadlock or a bad driver ?

Yes, TsWriter deadlock.
I'm almost certain it is caused by the EPG grabber.
Either corrupted data gets in and causes problems due to lack of proper checks in the code, or the code doesn't properly handle certain encodings... or something like that.

My guess is that you can't repro this issue on demand ?

Yes, correct.

 

[hucknallred]

All interesting stuff I must say, I don't know if this helps or not but I noticed this in the reservation line quoted:

tuningdetails=DVBS:radio:BSkyB Kismat Freq:12523000

Thing is I don't listen to Radio & certainly not this station & to my knowledge will not have tried to tune into it at all.
All the radio channels are tuned from the scan, but I never go there.

My guess is that you can't repro this issue on demand ?​

Yes, correct.

After posting last night, this happened again after the TV service restart, I'll try to reproduce the error again if it helps.
I am planning to go down the digiguide/xml route for the guide soon, but am happy to test this for the time being.

 

[gibman]

maybe it is the EPG grabber that tunes the channel ?

you can specify which channels the EPG should skip.

/gibman

 

[DJBlu]

Guys can you try this https://forum.team-mediaportal.com/threads/tswriter-deadlock-potential-fix.114898/