[confirm] DVB-S stops working after a while - More User have that problem (1 Viewer)

[mm1352000]

Hello again ramu

it's not easy to bring a problem to a point if it's not your mother tongue and only asyncron written communication...

Okay, understood.

I mean that I never got the message that there is no permission to see ORF using MP client. I do not have an idea why this error occurs?

So if you open MP and try to tune ORF III you will see video and hear sound?

So, am I right, this new log shows that MP server is grabbing on DVB-S card = card 4. ORF III channel is tuned. EPG is starting (thread EPG timer). Than thread 22 is handling the error message AND thrad 4 is grabbing EPG on that card successfully??? How can that happen if threaqd 22 tells us that we don't have permission?

First thing to say is that TV Server can't tell that the message from the CAM/smartcard is an error message.
Second, for EPG grabbing it doesn't matter that the channel is not decrypted. To understand this you need to understand how EPG is carried.
A frequency/transponder can carry zero or more channels plus the channel information (SI) plus extra information like EPG. The EPG could be carried without any channels if the provider wanted to do that. It is independent of the channel. In other words, you don't have to decrypt any channel to receive EPG. This situation that you're seeing in the log files is not a problem for the EPG grabber because although ORF III is encrypted, any EPG information carried on that transponder is not encrypted.

Tv server remembers the last client IP and tries to show CI menu on that client IP also there is no client running anymore?

Maybe... but this should not be a critical problem. If there is no client then an exception is thrown and caught. That is why you see:

[2013-12-28 02:54:18,202] [Log ] [22 ] [DEBUG] - TechnoTrend: OnDisplayMenu() exception: System.Net.Sockets.SocketException (0x80004005): Ein Verbindungsversuch ist fehlgeschlagen, da die Gegenstelle nach einer bestimmten Zeitspanne nicht richtig reagiert hat, oder die hergestellte Verbindung war fehlerhaft, da der verbundene Host nicht reagiert hat 53.2.172.238:62470

It means that TV Server tried to send the menu/info to MP but failed to contact MP... but that doesn't matter. Refer to the code:
https://github.com/MediaPortal/Medi...nalAccess/TechnoTrend/TechnoTrendAPI.cs#L1241

ciMenuCallbacks.OnCiMenu() and ciMenuCallbacks.OnCiMenuChoice() are trying to pass the information to MP. If they fail:

 catch (Exception ex)
 {
   Log.Log.Debug("TechnoTrend: OnDisplayMenu() exception: {0}", ex.ToString());
 }

...catch and log... but no serious problem. Why should the CAM/smartcard suddenly throw a tantrum? They don't even know that the delivery to MP failed!

I'm not sure if "only" this mishandling of CI menu information from MP causes my DVB-S problem???

Please explain with more detail: how do you think MP is mishandling this information? In other words, what should MP be doing instead and why would that solve the problem?

You asked for the real reason the problem. It's seams for me to be a communication problem between MP &TT card & CAM & crypto card, because the next time the permission to grab is allowed. And of course before it was also possible...

Hmmm, when you say "permission to grab is allowed"... I'm sorry but the logs are telling a different story.
On that day, each time the EPG grabber tries to grab EPG for ORF III:

[2013-12-25 23:23:22,695] [EPG ] [DVB EPG timer] [INFO ] - Grab for card:#4 transponder #29/30 channel: ORF III
[2013-12-25 23:23:26,456] [Log ] [8 ] [DEBUG] - TechnoTrend: 3: Keine Authorisation zum Sehen des Programms.
[2013-12-25 23:23:26,461] [Log ] [8 ] [DEBUG] - TechnoTrend: 4: Bitte kontaktieren Sie den Kundenservice.

[2013-12-26 00:26:54,548] [EPG ] [DVB EPG timer] [INFO ] - Grab for card:#4 transponder #29/30 channel: ORF III
[2013-12-26 00:26:58,244] [Log ] [8 ] [DEBUG] - TechnoTrend: 3: Keine Authorisation zum Sehen des Programms.
[2013-12-26 00:26:58,249] [Log ] [8 ] [DEBUG] - TechnoTrend: 4: Bitte kontaktieren Sie den Kundenservice.

[2013-12-26 01:32:26,461] [EPG ] [DVB EPG timer] [INFO ] - Grab for card:#4 transponder #29/30 channel: ORF III
[2013-12-26 01:32:30,782] [Log ] [8 ] [DEBUG] - TechnoTrend: 3: Keine Authorisation zum Sehen des Programms.
[2013-12-26 01:32:30,786] [Log ] [8 ] [DEBUG] - TechnoTrend: 4: Bitte kontaktieren Sie den Kundenservice.

Always the same message. Maybe at other times it is okay... but in each case TV Server is sending the same "please decrypt" message to the API. Reason for failure on that day is nothing to do with TV Server and something to do with the CAM, smartcard or driver.

Perhaps EPG is grabbing anyway also if that messages occurs (s. logs above?)

Yes, the EPG grabber is grabbing anyway. As explained above: decryption is not required for EPG grabbing... however if you had tried to timeshift that channel, it would have failed with "no PMT".

And I only found problems trying to reach ORF III? Did You see further channels causeing that problem in the logs?

Not in this set of logs, and not in the previous logs. These two sets of logs are the first time (in 2+ years???) that we have enough "history" to be able to see the start/cause of the problem.

Perhaps it's a timing problem because in manual use (with MP client) I didn't saw that message before? I mean perhaps MP is to quick to ask CI/CAM for actions???

I don't think so. If you look at the previous tune requests you can see that the CAM was already used without problems:
[collapse][2013-12-25 23:20:22,607] [EPG ] [DVB EPG timer] [INFO ] - Grab for card:#4 transponder #21/30 channel: ORF1 HD
...
[2013-12-25 23:20:23,779] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-25 23:20:23,784] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI statuslotModuleOk
[2013-12-25 23:20:23,787] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI text :TechniCrypt B2C
[2013-12-25 23:20:23,791] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: ca system id 05
[2013-12-25 23:20:23,795] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple1)
[2013-12-25 23:20:23,799] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:4911
[2013-12-25 23:20:23,803] [Log ] [DVB EPG timer] [DEBUG] - $ OnCaChange slot:255 reply:E status:0
[2013-12-25 23:20:23,807] [Log ] [DVB EPG timer] [DEBUG] - $ CI: SetProgram OK
[2013-12-25 23:20:24,606] [Log ] [DVB EPG timer] [DEBUG] - $ OnCaChange slot:255 reply:E status:0
[2013-12-25 23:20:24,611] [Log ] [DVB EPG timer] [DEBUG] - $ CI: SetProgram OK
[2013-12-25 23:20:24,615] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: services decodeduccess 1
[/collapse]

Further, in later logs we can see an example of what happens when TV Server tries to access the CI/CAM too quickly:
[collapse]
[2013-12-27 11:41:18,320] [EPG ] [DVB EPG timer] [INFO ] - Grab for card:#4 transponder #29/30 channel: ORF III
[2013-12-27 11:41:18,325] [EPG ] [DVB EPG timer] [INFO ] - EpgCard: grab epg on card: #4 transponder: #28 ch:ORF III
[2013-12-27 11:41:18,340] [Log ] [DVB EPG timer] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=272, tuningdetails=DVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-12-27 11:41:18,344] [Log ] [DVB EPG timer] [INFO ] - card: Tune on card 4 to subchannel ORF III
[2013-12-27 11:41:18,349] [Log ] [DVB EPG timer] [DEBUG] - card: user: epg:4:-1 tune DVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-12-27 11:41:18,359] [Log ] [DVB EPG timer] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
[2013-12-27 11:41:18,364] [Log ] [DVB EPG timer] [INFO ] - dvbs: TuneVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-12-27 11:41:18,369] [Log ] [DVB EPG timer] [INFO ] - dvbs: TuneVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-12-27 11:41:18,374] [Log ] [DVB EPG timer] [INFO ] - dvbs:BuildGraph
[2013-12-27 11:41:18,380] [Log ] [DVB EPG timer] [INFO ] - dvb:AddNetworkProviderFilter
[2013-12-27 11:41:18,385] [Log ] [DVB EPG timer] [INFO ] - dvb:AddNetworkProviderFilter
[2013-12-27 11:41:18,391] [Log ] [DVB EPG timer] [INFO ] - dvb:Add Generic Network Provider
[2013-12-27 11:41:18,397] [Log ] [DVB EPG timer] [INFO ] - dvb: Add Mediaportal TsWriter filter
[2013-12-27 11:41:18,403] [Log ] [DVB EPG timer] [INFO ] - dvbs:CreateTuningSpace()
[2013-12-27 11:41:18,418] [Log ] [DVB EPG timer] [INFO ] - dvbs:found correct tuningspace MediaPortal DVBS TuningSpace
[2013-12-27 11:41:18,423] [Log ] [DVB EPG timer] [INFO ] - dvb:Add MPEG2 Demultiplexer filter
[2013-12-27 11:41:18,427] [Log ] [DVB EPG timer] [INFO ] - dvb:AddAndConnectBDABoardFilters
[2013-12-27 11:41:18,431] [Log ] [DVB EPG timer] [INFO ] - dvb: find bda tuner
[2013-12-27 11:41:18,459] [Log ] [DVB EPG timer] [INFO ] - dvb: using [Tuner]: TechnoTrend BDA/DVB-S Tuner
[2013-12-27 11:41:18,463] [Log ] [DVB EPG timer] [INFO ] - dvb: Render [Network provider]->[Tuner] OK
[2013-12-27 11:41:18,467] [Log ] [DVB EPG timer] [INFO ] - dvb: Setting lastFilter to Tuner filter
[2013-12-27 11:41:18,471] [Log ] [DVB EPG timer] [INFO ] - dvb: Find BDA receiver
[2013-12-27 11:41:18,474] [Log ] [DVB EPG timer] [INFO ] - dvb: match Capture by Tuner device path
[2013-12-27 11:41:18,483] [Log ] [DVB EPG timer] [INFO ] - dvb: -TechnoTrend BDA/DVB Capture
[2013-12-27 11:41:18,493] [Log ] [DVB EPG timer] [INFO ] - dvb: Render [Tuner]->[Capture] AOK
[2013-12-27 11:41:18,497] [Log ] [DVB EPG timer] [INFO ] - dvb: Setting lastFilter to Capture device
[2013-12-27 11:41:18,504] [Log ] [DVB EPG timer] [INFO ] - dvb: WinTv CI module not detected.
[2013-12-27 11:41:18,508] [Log ] [DVB EPG timer] [INFO ] - dvb:add Inf Tee filter
[2013-12-27 11:41:18,513] [Log ] [DVB EPG timer] [INFO ] - dvb: Render ...->[inftee]
[2013-12-27 11:41:18,518] [Log ] [DVB EPG timer] [INFO ] - dvb: Setting lastFilter to Inf Tee
[2013-12-27 11:41:18,522] [Log ] [DVB EPG timer] [INFO ] - dvb: Render [inftee]->[demux]
[2013-12-27 11:41:18,528] [Log ] [DVB EPG timer] [INFO ] - dvb: AddTransportStreamFiltersToGraph
[2013-12-27 11:41:18,532] [Log ] [DVB EPG timer] [INFO ] - add BDA MPEG2 Transport Information Filter filter
[2013-12-27 11:41:18,537] [Log ] [DVB EPG timer] [INFO ] - pinTif:name:IB Input [3/0] Direction:Input Connected:False
[2013-12-27 11:41:18,541] [Log ] [DVB EPG timer] [INFO ] - Connect tif and mpeg2 sections and tables
[2013-12-27 11:41:18,545] [Log ] [DVB EPG timer] [INFO ] - dvb:try tif:name:001 [5/0] Direction:Output Connected:False
[2013-12-27 11:41:18,549] [Log ] [DVB EPG timer] [INFO ] - tif connected
[2013-12-27 11:41:18,554] [Log ] [DVB EPG timer] [INFO ] - dvb: Render ..->[TsWriter]
[2013-12-27 11:41:18,559] [Log ] [DVB EPG timer] [INFO ] - dvb: Checking for hardware specific extensions
[2013-12-27 11:41:18,563] [Log ] [DVB EPG timer] [INFO ] - CAM is Default model
[2013-12-27 11:41:18,567] [Log ] [DVB EPG timer] [INFO ] - Check for KNC
[2013-12-27 11:41:18,573] [Log ] [DVB EPG timer] [INFO ] - KNC: IsKNC False
[2013-12-27 11:41:18,577] [Log ] [DVB EPG timer] [DEBUG] - KNC: Disable CI
[2013-12-27 11:41:18,581] [Log ] [DVB EPG timer] [DEBUG] - KNC: Disposing CI handler
[2013-12-27 11:41:18,585] [Log ] [DVB EPG timer] [INFO ] - Check for Digital Everywhere
[2013-12-27 11:41:18,589] [Log ] [DVB EPG timer] [INFO ] - Check for Twinhan
[2013-12-27 11:41:18,592] [Log ] [DVB EPG timer] [INFO ] - Twinhan: CI detection finished
[2013-12-27 11:41:18,597] [Log ] [DVB EPG timer] [INFO ] - Check for TechnoTrend
[2013-12-27 11:41:18,624] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: initalized id:23, driver version:5.0.1.8
[2013-12-27 11:41:18,628] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: OpenCI succeeded
[2013-12-27 11:41:18,632] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend card detected
[2013-12-27 11:41:18,725] [Log ] [DVB EPG timer] [INFO ] - dvb: GetTunerSignalStatistics()
[2013-12-27 11:41:18,730] [Log ] [DVB EPG timer] [INFO ] - dvb:GetNewSubChannel:0 #0
[2013-12-27 11:41:18,735] [Log ] [DVB EPG timer] [INFO ] - TvDvbChannel ctor new subchIndex:0
[2013-12-27 11:41:18,739] [Log ] [DVB EPG timer] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
[2013-12-27 11:41:18,743] [Log ] [DVB EPG timer] [INFO ] - LNB low:9750 hi:10600 switch:11700
[2013-12-27 11:41:18,747] [Log ] [DVB EPG timer] [INFO ] - Technotrend DVB-S2 modulation set to:ModNotSet
[2013-12-27 11:41:18,751] [Log ] [DVB EPG timer] [INFO ] - Technotrend DVB-S2 Pilot set to:NotSet
[2013-12-27 11:41:18,755] [Log ] [DVB EPG timer] [INFO ] - Technotrend DVB-S2 RollOff set to:NotSet
[2013-12-27 11:41:18,760] [Log ] [DVB EPG timer] [INFO ] - Technotrend DVB-S2 fec set to:Rate5_6
[2013-12-27 11:41:18,764] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel modulation is set to ModNotSet
[2013-12-27 11:41:18,768] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel FECRate is set to Rate5_6
[2013-12-27 11:41:18,771] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend SendDiseqcCommand() diseqc:None, antenna:0 frequency:12663000, polarisation:LinearH hiband:True
[2013-12-27 11:41:19,036] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend: Diseqc Command Send
[2013-12-27 11:41:19,141] [Log ] [DVB EPG timer] [INFO ] - dvbubmiting tunerequest Channel:ORF III subChannel:0
[2013-12-27 11:41:19,147] [Log ] [DVB EPG timer] [INFO ] - dvb:using existing subchannel:0
[2013-12-27 11:41:19,151] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest size:1 new:0
[2013-12-27 11:41:19,155] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnBeforeTune
[2013-12-27 11:41:19,159] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest calling put_TuneRequest
[2013-12-27 11:41:19,163] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest done calling put_TuneRequest
[2013-12-27 11:41:19,167] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnAfterTune
[2013-12-27 11:41:19,170] [Log ] [DVB EPG timer] [INFO ] - RunGraph
[2013-12-27 11:41:19,174] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStart
[2013-12-27 11:41:19,178] [Log ] [DVB EPG timer] [INFO ] - dvb: RunGraph
[2013-12-27 11:41:19,353] [Log ] [DVB EPG timer] [INFO ] - dvb: LockInOnSignal ok
[2013-12-27 11:41:19,358] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStarted
[2013-12-27 11:41:19,362] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetupPmtGrabberid 44D sid:332D
[2013-12-27 11:41:19,366] [Log ] [DVB EPG timer] [INFO ] - subch:0 set pmt grabber pmt:44D sid:332D
[2013-12-27 11:41:19,369] [Log ] [DVB EPG timer] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2013-12-27 11:41:19,374] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Waiting for PMT 44D
[2013-12-27 11:41:20,673] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:20,877] [Log ] [50 ] [INFO ] - subch:0 OnPMTReceived() pmt:44D ran:True dynamic:False
[2013-12-27 11:41:20,882] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Found PMT after 1,5090863 seconds.
[2013-12-27 11:41:20,887] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt:332D 332D FFFFFFFF 0
[2013-12-27 11:41:20,891] [Log ] [DVB EPG timer] [INFO ] - Decode pmt
[2013-12-27 11:41:20,895] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 95 e0 dc
[2013-12-27 11:41:20,899] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 48 e0 6e
[2013-12-27 11:41:20,903] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 5 e0 d2
[2013-12-27 11:41:20,907] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 c4 e1 e0
[2013-12-27 11:41:20,911] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 17 2 e1 36
[2013-12-27 11:41:20,915] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 18 33 e1 9a
[2013-12-27 11:41:20,919] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 8c e1 ea
[2013-12-27 11:41:20,923] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 98 e0 dd
[2013-12-27 11:41:20,927] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 50 e0 6f
[2013-12-27 11:41:20,931] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:20,935] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:20,938] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 6 9
[2013-12-27 11:41:20,942] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 7
[2013-12-27 11:41:20,946] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 3 10
[2013-12-27 11:41:20,950] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:20,954] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPMT version:0 len:131 13101
[2013-12-27 11:41:20,958] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:20,962] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple1)
[2013-12-27 11:41:20,966] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:13101
[2013-12-27 11:41:20,970] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI module inserted but not yet ready
[2013-12-27 11:41:20,974] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:False
[2013-12-27 11:41:20,978] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt failed cam flags:False
[2013-12-27 11:41:20,982] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: waiting for SendPmtToCam 1513,0865 ms.
[2013-12-27 11:41:23,985] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt:332D 332D FFFFFFFF 0
[2013-12-27 11:41:23,989] [Log ] [DVB EPG timer] [INFO ] - Decode pmt
[2013-12-27 11:41:23,993] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 95 e0 dc
[2013-12-27 11:41:23,999] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 48 e0 6e
[2013-12-27 11:41:24,003] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 5 e0 d2
[2013-12-27 11:41:24,008] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 c4 e1 e0
[2013-12-27 11:41:24,012] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 17 2 e1 36
[2013-12-27 11:41:24,016] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 18 33 e1 9a
[2013-12-27 11:41:24,021] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 8c e1 ea
[2013-12-27 11:41:24,025] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 98 e0 dd
[2013-12-27 11:41:24,029] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 50 e0 6f
[2013-12-27 11:41:24,033] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:24,038] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:24,042] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 6 9
[2013-12-27 11:41:24,047] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 7
[2013-12-27 11:41:24,052] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 3 10
[2013-12-27 11:41:24,056] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:24,060] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPMT version:0 len:131 13101
[2013-12-27 11:41:24,064] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:24,068] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple1)
[2013-12-27 11:41:24,072] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:13101
[2013-12-27 11:41:24,076] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI module inserted but not yet ready
[2013-12-27 11:41:24,081] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:False
[2013-12-27 11:41:24,085] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt failed cam flags:False
[2013-12-27 11:41:24,089] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: waiting for SendPmtToCam 4612,2638 ms.
[2013-12-27 11:41:27,093] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt:332D 332D FFFFFFFF 0
[2013-12-27 11:41:27,097] [Log ] [DVB EPG timer] [INFO ] - Decode pmt
[2013-12-27 11:41:27,102] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 95 e0 dc
[2013-12-27 11:41:27,106] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 48 e0 6e
[2013-12-27 11:41:27,110] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 5 e0 d2
[2013-12-27 11:41:27,115] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 c4 e1 e0
[2013-12-27 11:41:27,120] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 17 2 e1 36
[2013-12-27 11:41:27,124] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 18 33 e1 9a
[2013-12-27 11:41:27,128] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 8c e1 ea
[2013-12-27 11:41:27,132] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 98 e0 dd
[2013-12-27 11:41:27,136] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 50 e0 6f
[2013-12-27 11:41:27,139] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:27,143] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:27,146] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 6 9
[2013-12-27 11:41:27,150] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 7
[2013-12-27 11:41:27,154] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 3 10
[2013-12-27 11:41:27,158] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:27,162] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPMT version:0 len:131 13101
[2013-12-27 11:41:27,167] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:27,171] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI statuslotModuleOk
[2013-12-27 11:41:27,175] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI text :TechniCrypt B2C
[2013-12-27 11:41:27,178] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple1)
[2013-12-27 11:41:27,182] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:13101
[2013-12-27 11:41:27,575] [Log ] [DVB EPG timer] [DEBUG] - $ OnCaChange slot:255 reply:E status:5
[2013-12-27 11:41:27,580] [Log ] [DVB EPG timer] [DEBUG] - $ CI: ERROR:etProgram failed !!! (no CA resource available)
[2013-12-27 11:41:27,584] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: services not decodeduccess ciStatus: -1
[2013-12-27 11:41:27,589] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:True
[2013-12-27 11:41:27,593] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt failed cam flags:True
[2013-12-27 11:41:27,597] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: waiting for SendPmtToCam 7720,4415 ms.
[2013-12-27 11:41:28,707] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:28,711] [Log ] [12 ] [DEBUG] - TechnoTrend: CI statuslotModuleOk
[2013-12-27 11:41:28,716] [Log ] [12 ] [DEBUG] - TechnoTrend: CI text :TechniCrypt B2C
[2013-12-27 11:41:28,720] [Log ] [12 ] [DEBUG] - TechnoTrend: ca system id 05
[2013-12-27 11:41:30,601] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPmt:332D 332D FFFFFFFF 0
[2013-12-27 11:41:30,605] [Log ] [DVB EPG timer] [INFO ] - Decode pmt
[2013-12-27 11:41:30,609] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 95 e0 dc
[2013-12-27 11:41:30,614] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 48 e0 6e
[2013-12-27 11:41:30,618] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 5 e0 d2
[2013-12-27 11:41:30,622] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 c4 e1 e0
[2013-12-27 11:41:30,626] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 17 2 e1 36
[2013-12-27 11:41:30,630] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 18 33 e1 9a
[2013-12-27 11:41:30,633] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 9 8c e1 ea
[2013-12-27 11:41:30,637] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 d 98 e0 dd
[2013-12-27 11:41:30,641] [Log ] [DVB EPG timer] [INFO ] - descr1 len:6 9 4 6 50 e0 6f
[2013-12-27 11:41:30,645] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:30,648] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:30,652] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 6 9
[2013-12-27 11:41:30,656] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 7
[2013-12-27 11:41:30,660] [Log ] [DVB EPG timer] [INFO ] - PROBLEM : descriptor lengths dont match 3 10
[2013-12-27 11:41:30,664] [Log ] [DVB EPG timer] [INFO ] - Set descriptor data with length 3
[2013-12-27 11:41:30,670] [Log ] [DVB EPG timer] [INFO ] - subch:0 SendPMT version:0 len:131 13101
[2013-12-27 11:41:30,674] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: slot 0 changed
[2013-12-27 11:41:30,678] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI statuslotModuleOk
[2013-12-27 11:41:30,682] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: CI text :TechniCrypt B2C
[2013-12-27 11:41:30,685] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: ca system id 05
[2013-12-27 11:41:30,689] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple1)
[2013-12-27 11:41:30,692] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:13101
[2013-12-27 11:41:30,696] [Log ] [DVB EPG timer] [DEBUG] - $ OnCaChange slot:255 reply:E status:0
[2013-12-27 11:41:30,699] [Log ] [DVB EPG timer] [DEBUG] - $ CI: SetProgram OK
[2013-12-27 11:41:31,199] [Log ] [DVB EPG timer] [DEBUG] - $ OnCaChange slot:255 reply:E status:0
[2013-12-27 11:41:31,203] [Log ] [DVB EPG timer] [DEBUG] - $ CI: SetProgram OK
[2013-12-27 11:41:31,207] [Log ] [DVB EPG timer] [DEBUG] - TechnoTrend: services decodeduccess 1
[2013-12-27 11:41:31,212] [Log ] [DVB EPG timer] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:True
[2013-12-27 11:41:31,215] [Log ] [DVB EPG timer] [INFO ] - subch:0 cam flags:True
[2013-12-27 11:41:31,220] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetMpegPidMapping
[2013-12-27 11:41:31,224] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:3F2 pcr
[2013-12-27 11:41:31,228] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:44D pmt
[2013-12-27 11:41:31,232] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:3F2 video type:MPEG-2
[2013-12-27 11:41:31,235] [Log ] [DVB EPG timer] [INFO ] - subch:0 map pid:3F2 video type:MPEG-2
[2013-12-27 11:41:31,240] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:3F3 audio lang:ger type:MPEG-2
[2013-12-27 11:41:31,243] [Log ] [DVB EPG timer] [INFO ] - subch:0 map pid:3F3 audio lang:ger type:MPEG-2
[2013-12-27 11:41:31,247] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:3F5 teletext type:6
[2013-12-27 11:41:31,251] [Log ] [DVB EPG timer] [INFO ] - subch:0 map pid:3F5 teletext type:6
[2013-12-27 11:41:31,255] [Log ] [DVB EPG timer] [INFO ] - subch:0 pid:3F7 type:6
[2013-12-27 11:41:31,259] [Log ] [DVB EPG timer] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
[2013-12-27 11:41:31,263] [Log ] [DVB EPG timer] [INFO ] - subch:0 stop tif
[2013-12-27 11:41:31,267] [Log ] [DVB EPG timer] [DEBUG] - WaitForPmt: PMT handling took 10,3815938 seconds.
[2013-12-27 11:41:31,296] [Log ] [DVB EPG timer] [DEBUG] - card: Tuner locked: True
[2013-12-27 11:41:31,300] [Log ] [DVB EPG timer] [INFO ] - **************************************************
[2013-12-27 11:41:31,306] [Log ] [DVB EPG timer] [INFO ] - ***** SIGNAL LEVEL: 79, SIGNAL QUALITY: 100 *****
[2013-12-27 11:41:31,310] [Log ] [DVB EPG timer] [INFO ] - **************************************************
[2013-12-27 11:41:31,314] [Log ] [DVB EPG timer] [DEBUG] - card: tuned user: epg subchannel: 0
[2013-12-27 11:41:31,319] [Log ] [DVB EPG timer] [INFO ] - user:epg add
[2013-12-27 11:41:31,323] [Log ] [DVB EPG timer] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=272, tuningdetails=DVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-12-27 11:41:31,327] [Log ] [DVB EPG timer] [INFO ] - card: SignalTuneEvent card: 4 / subch: 0
[2013-12-27 11:41:31,332] [Log ] [DVB EPG timer] [INFO ] - Controller: GrabEpg on card ID == 4
[2013-12-27 11:41:31,336] [EPG ] [DVB EPG timer] [INFO ] - EpgGrabbing: Start
[2013-12-27 11:41:31,342] [Log ] [DVB EPG timer] [INFO ] - dvb:grab epg...
[2013-12-27 11:41:31,347] [EPG ] [DVB EPG timer] [INFO ] - EpgCard: card: 4 starting to grab DVBS:tv:ORF ORF III Freq:12663000 ONID:1 TSID:1115 SID:13101 PMT:0x44D FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet[/collapse]

We retry... and eventually get success.

So, I don't think it is timing.

My question is: why did the CAM/smartcard/driver suddenly start to fail for ORF III?

Anyway I'm wondering if it's possible to catch this error message in MP for EPG user to prevent this deadlock? Is it for e.g. possible to implement a second try from MP for accessing CAM when this kind of error is coming up or just to skip this request, reset grahp and try next channel? It should be no big effort to implement a error/exception handling for that issue i hope.

As I showed above with the code: we do already catch the error message.
As I showed above with the logs: we do implement a second try (and third and forth...) when the CI/CAM reports it is not ready.

TV Server can't tell that the message from the CAM/smartcard means that the CAM/smartcard are "borked". The message might just mean that you tried to receive a channel that is not part of your subscription, and the CAM/smartcard are still okay. Further, the messages from different CAMs/smartcards are all different. There is no way for TV Server to say "okay, that message means that we need to reset the tuner or CI".

Well, I connected TT, they want to help and they ask for a detailed problem information. What should I ask them for?

You can ask them:
1. Why your tuner suddenly fails to decrypt channels which are part of your subscription.
2. Why the tuner stops streaming after such a failure.

Do You know where this exception is coming from, found several in logs of last days. But I don't know if they are coming from the experiment with this debug option...

It comes from the debug option experiment.

mm

 

[ramu]

Hi FreakyJ, hi pünktchen,

You are right, it's CI -> Cam -> Smart card,I mixed up the technical terms

• CI-Adapter from Technotrend belonging to S2-3200 card (TT-budget BDA-Treiber 5.0.1.8 (16.01.09))
  
• TechniCrypt B2C CAM-Modul by Technisat (SW V26.8.5.0.7)
  
• Cryptoworks Smartcard

So, right now, I'm waiting for the next occurence of that problem. Unfortunaltely I do not have any idae to reproduce this right now... Than I will pull Smartcard and see what happens.

Meanwhile I'll ask TT if they can explain that behavior.

ramu

 

[FreakyJ]

Than I will pull Smartcard and see what happens.

Better would be to pull the Cam, wait 10 sec, reinsert the cam, wait again 20 sec. And try again if you now can watch the channel

 

[ramu]

I did what You said, pulled CAM and waited for a minute. Unfortunately there is no other behaivor. No DVB-S channel is aviable.

Also I didn't saw anything in tvserver.log that I pulled the cam card. Does MP logs such event?

Afterwards I added an other crypted channel to my DVB-S group. I thought I'll get the same error message as we saw in the logs some CI window with such an information:

[2013-12-26 00:26:58,244] [Log ] [8 ] [DEBUG] - TechnoTrend: 3: Keine Authorisation zum Sehen des Programms.
[2013-12-26 00:26:58,249] [Log ] [8 ] [DEBUG] - TechnoTrend: 4: Bitte kontaktieren Sie den Kundenservice.

So I waited for a message coming from CI something with 4 lines like CI Menue. But obviously MP handles this situation in an other way if pmt informations are there. I only got the info that this channel is crypted...

Now I'm wondering why and where the difference is. In this case I try to watch a channel I don't have a Smartcard for and in the error state in my problem case, there is a Smartcard? In the first case I only get a normal information window and not the same information in logs like in the error case, which looks like CI menue..

ramu

 

[mm1352000]

I did what You said, pulled CAM and waited for a minute. Unfortunately there is no other behaivor. No DVB-S channel is aviable.

Did you try tuning again after pulling and reinserting the CAM?

Also I didn't saw anything in tvserver.log that I pulled the cam card. Does MP logs such event?

Should do:
https://github.com/MediaPortal/Medi...nalAccess/TechnoTrend/TechnoTrendAPI.cs#L1121

Something like "TechnoTrend: slot {0} changed" + "TechnoTrend: CI status:{0}".

BUT... this only happens if you pull the CAM, not the smartcard.

mm

 

[ramu]

Hi,

I'm sorry, I didn't pulled CAM module, I pulled only smartcard and used the wrong description.

But now I pulled out both (Technisat CAM and Smartcard), waited for 15 s and after reinsering everything worked well afterwards!!!

Have a look on attachted log.

[2014-01-01 20:15:59,884] [Log ] [21 ] [DEBUG] - TechnoTrend: slot 0 changed
[2014-01-01 20:15:59,985] [Log ] [18 ] [INFO ] - subch:0 OnPMTReceived() pmt:19C8 ran:True dynamic:False

ramu

 

[mm1352000]

Hello again ramu

I'm sorry, I didn't pulled CAM module, I pulled only smartcard and used the wrong description.

But now I pulled out both (Technisat CAM and Smartcard), waited for 15 s and after reinsering everything worked well afterwards!!!

Great - so now we finally have 100% proof that the issue is caused by your CAM or smartcard. Now the only question: is TV Server triggering the problem somehow.

mm

 

[ramu]

Hello mm,

ok. - Do You have any idea how to find out if TV Server is causing that problem? Can I test something, e.g. a special debug patch?

What about something like a small plugin only grabbing ORF frequenz with different time intervalls and counting the grabbing attemp?

By the way ORF III is the only crypted channel on this frequenz in diefferenz to ORF 1/2/xxx where more crypted channeles are on one frequenz. Does this make any sence to my problem?

ramu

 

[mm1352000]

ok. - Do You have any idea how to find out if TV Server is causing that problem? Can I test something, e.g. a special debug patch?

No. I'd say the best thing to do is to keep posting full log files every time the problem occurs. Hopefully we will be able to see a pattern - maybe with one channel, or a certain CAM/CI interaction - that will enable us to solve or workaround the problem.

 

[ramu]

Very well, here are full logs for You.

Just found in a telehone call with technisat out, that there is a small difference in the way ORF x and ORF III is crypted.

Where ORF x is only cyrpted by Cyroptoworks standard D05 and D95. ORF III uses D05, D95 and D98. Perhaps that helps???

ramu