[confirm] CAM Support Problem (1 Viewer)

[ramu]

Hello,
need Your help. MP 1.3 Alpha is running well. But there is a problem using CAM with DVB-S Technotrend S2 DBA driver for encrypted channels:
- New start of MP Server, everything works well.
- Not using MP for some time
- Trying to see encrypted channels MP throws errors e.g. ”no graph building possible” or “channel not found”??
- With my DVB-T cards there are no problems, channels will be displayed normally.
After restarting MP service everything works well again, also encrypted channels are displayed.
Please, have a look to the attached logs. For example I found a difference that the signal level before and after restart on the same channel are not the same???
Perhaps there is a problem restarting the BDA driver / CAM module after a while. Well, I’ve checked the TV server setup, all cards are in “stop-mode”. I thought the cards gets a complete init before reusing. Could there be an error that the CAM module is not completely reinitialized?
ramu

 

[mm1352000]

Hello ramu

Did you also have this problem with MP 1.2.x?
Please tell us: which tuner model is it (eg. Budget S2-3200)?

According to the logs, the reason for the tuning failures was:

TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:False

So the TT driver was telling TV Server that the CAM was in the slot, but that it wasn't ready to be used yet. Each time TV Server tries to tune an encrypted channel it retries 5 times over ~15 seconds. All attempts were failing since before the logs start - at least 2012-07-30 03:36:00...

mm

 

[ramu]

Hello mm,

You are right, Its a budget S2-3200 PCI card and this problem occoured also with MP 1.2.x.

I'm sure that I don't touch the CAM card at the server. So I don't belie that there could be a hardware defect, because after restart the system ist running well. I've seen that signal level before and after restart of MP server are different, perhapse in the first time the signal is to low for CAM moduel to work?

Sometimes the whole systems which means the MP-server stops or hangs until the restart of the service or PC. I'm sure you can also find the right positions into the logs...

Thx for helping
ramu

 

[mm1352000]

Hello again

You are right, Its a budget S2-3200 PCI card and this problem occoured also with MP 1.2.x.

Thanks.

I'm sure that I don't touch the CAM card at the server. So I don't belie that there could be a hardware defect, because after restart the system ist running well.

The next time the problem happens, can you try to reinsert the CAM and see if it fixes the problem?

I've seen that signal level before and after restart of MP server are different, perhapse in the first time the signal is to low for CAM moduel to work?

I guess the CAM module firmware could crash if the signal is very bad. However this is just speculation. I suspect TT driver issues are the more likely cause.

If you want me to try to fix this problem then I need to see logs that show when the problem starts. The logs that you already provided do not show this - the problem is already occurring at the start of the logs. If I can't see the situation that is causing the problem then it is very hard to try to fix it or make a workaround.

mm

 

[ramu]

Hi mm,

thx for Your response. I'll try after my holiday to reinsert cam card when this problem occurs next. But I need a tip who to log the periode You need to solve this error.

By the way I don't belive that it's a fimrware problem, because I've checked the system with tt-viewer in this error state. There the DVB-T card didn't cause any trouble also encrypted channels are displayed...

ramu

 

[mm1352000]

Hello again

thx for Your response. I'll try after my holiday to reinsert cam card when this problem occurs next.

Okay, thank you.

But I need a tip who to log the periode You need to solve this error.

Basically try to grab the logs, as soon as you see the problem. It may be a case of luck. In this case I don't mind if you provide many log files. I am mostly only interested in the tv.log and tv.bak files. You can grab those files by:
1. Open TV Server configuration.
2. Click "open log directory" in the top left corner.

TV Server logs are in that folder.

By the way I don't belive that it's a fimrware problem, because I've checked the system with tt-viewer in this error state. There the DVB-T card didn't cause any trouble also encrypted channels are displayed...

MP also works after you restart the TV service. Restarting the service (or using TT-Viewer) probably resets the CAM/tuner driver state. We could possibly do this automatically if we can detect the start of the problem. This is why I am interested in the log files - to try to see exactly what is happening when the problem starts.

mm

 

[ramu]

Hi mm,

back from holiday I tried to export the TV logs for bugfixing the Technotrend problem. While trying to start mediaportal again I got a server exception several times? See attachted screenshot.

I took my formaly to MP attached external DVB-T nebula box with me on holiday and didn't reconected it since. But in between I restarted MP and the server 3x times. Could that be the case of that error message?

Also I will attach actuall logs for You perhaps in there You'll find the reason not only for that exeception but also for the technotrend problem...

Thx
ramu

 

[ramu]

Hello,

unfortunaltly MP is stil not running. While starting MP I got this error (from error.log). Is there anyone who can help ?

ramu

2012-08-26 20:16:27.593750 [DVB EPG timer(9)]: Exception ystem.Runtime.Remoting.RemotingException: Der angeforderte Dienst wurde nicht gefunden.

Server stack trace:
bei System.Runtime.Remoting.Channels.BinaryServerFormatterSink.ProcessMessage(IServerChannelSinkStack sinkStack, IMessage requestMsg, ITransportHeaders requestHeaders, Stream requestStream, IMessage& responseMsg, ITransportHeaders& responseHeaders, Stream& responseStream)

Exception rethrown at [0]:
bei System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
bei System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
bei TvControl.IController.IsRecording(IUser& user)
bei TvService.EpgCard.IsCardIdle(Int32 cardId)
bei TvService.EpgCard.GrabEpgForChannel(Channel channel, IChannel tuning, Card card)
bei TvService.EpgCard.GrabEpg()
bei TvService.EpgGrabber.GrabEpgOnCard(EpgCard epgCard)
bei TvService.EpgGrabber._epgTimer_Elapsed(Object sender, ElapsedEventArgs e)

2012-08-26 21:51:11.343750 [DVB EPG timer(9)]: Exception ystem.Runtime.Remoting.RemotingException: Der angeforderte Dienst wurde nicht gefunden.

Server stack trace:
bei System.Runtime.Remoting.Channels.BinaryServerFormatterSink.ProcessMessage(IServerChannelSinkStack sinkStack, IMessage requestMsg, ITransportHeaders requestHeaders, Stream requestStream, IMessage& responseMsg, ITransportHeaders& responseHeaders, Stream& responseStream)

Exception rethrown at [0]:
bei System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
bei System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
bei TvControl.IController.IsRecording(IUser& user)
bei TvService.EpgCard.IsCardIdle(Int32 cardId)
bei TvService.EpgCard.GrabEpgForChannel(Channel channel, IChannel tuning, Card card)
bei TvService.EpgCard.GrabEpg()
bei TvService.EpgGrabber.GrabEpgOnCard(EpgCard epgCard)
bei TvService.EpgGrabber._epgTimer_Elapsed(Object sender, ElapsedEventArgs e)

 

[ramu]

Hi mm,

so back from holiday I restartet MP because nothing was running welll. No TV and no epg.

After restart MP runs for about 1 day. Next evening no pricture and also new problems with epg.

So have a loo to both of the attachted logs, please. I would be happy to get a MP version without these start / restart problems for DVB-S and DVB-T, because there is also no tv at the moment.

Please give me feedback if You need some more informations or if there is anything to test.

Thanks
ramu

 

[mm1352000]

Hello ramu

I hope the holiday was good!

These log files are perfect - just what I needed.

From the tv.log, the biggest problem is this:
[collapse]2012-10-07 01:04:16.625000 [EPG Update thread(19)]: Tvservice stopped due to an unhandled app domain exception System.AccessViolationException: Es wurde versucht, im geschützten Speicher zu lesen oder zu schreiben. Dies ist häufig ein Hinweis darauf, dass anderer Speicher beschädigt ist.
bei DirectShowLib.IMediaControl.Stop()
bei TvLibrary.Implementations.DVB.TvCardDvbBase.StopGraph()
bei TvLibrary.Implementations.DVB.TvCardDVBS.StopGraph()
bei TvLibrary.Implementations.TvCardBase.FreeSubChannel(Int32 id)
bei TvLibrary.Implementations.DVB.TvCardDvbBase.FreeSubChannel(Int32 id)
bei TvService.EpgGrabbing.Stop(IUser user)
bei TvService.TVController.StopGrabbingEpg(IUser user)
bei TvService.EpgCard.UpdateDatabaseThread()
bei System.Threading.ThreadHelper.ThreadStart_Context(Object state)
bei System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
bei System.Threading.ThreadHelper.ThreadStart()[/collapse]
TV Server is crashing when it tries to stop the TechnoTrend tuner. This happens twice in both of your log sets - 4 times in total. *Very* unusual.

I also see this in the most recent log files:
[collapse]dvbs: TuneVBS:tvroSiebenSat.1 PULS 4 Austria Freq:12051000 ONID:1 TSID:1082 SID:20007 PMT:0x66 FTA:False LCN:446 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-10-05 21:53:16.312500 [DVB EPG timer(13)]: dvb:GetNewSubChannel:0 #0
2012-10-05 21:53:16.328125 [DVB EPG timer(13)]: TvDvbChannel ctor new subchIndex:0
2012-10-05 21:53:16.328125 [DVB EPG timer(13)]: card: AddTuneEvent card: 3 / subch: 0
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: LNB low:9750 hi:10600 switch:11700
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: Technotrend DVB-S2 modulation set to:ModNotSet
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: Technotrend DVB-S2 Pilot set to:NotSet
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: Technotrend DVB-S2 RollOff set to:NotSet
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: Technotrend DVB-S2 fec set to:Rate3_4
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: dvbs:channel modulation is set to ModNotSet
2012-10-05 21:53:16.343750 [DVB EPG timer(13)]: dvbs:channel FECRate is set to Rate3_4
2012-10-05 21:53:16.359375 [DVB EPG timer(13)]: TechnoTrend SendDiseqcCommand() diseqc:None, antenna:0 frequency:12051000, polarisation:LinearV hiband:True
2012-10-05 21:53:16.625000 [DVB EPG timer(13)]: TechnoTrend: Diseqc Command Send
2012-10-05 21:53:16.734375 [DVB EPG timer(13)]: dvbubmiting tunerequest ChannelULS 4 Austria subChannel:0
2012-10-05 21:53:16.734375 [DVB EPG timer(13)]: dvb:using existing subchannel:0
2012-10-05 21:53:16.734375 [DVB EPG timer(13)]: dvbubmit tunerequest size:1 new:0
2012-10-05 21:53:16.734375 [DVB EPG timer(13)]: subch:0 OnBeforeTune
2012-10-05 21:53:16.734375 [DVB EPG timer(13)]: dvbubmit tunerequest calling put_TuneRequest
2012-10-05 21:53:17.515625 [DVB EPG timer(13)]: dvbubmit tunerequest done calling put_TuneRequest
2012-10-05 21:53:17.515625 [DVB EPG timer(13)]: subch:0 OnAfterTune
2012-10-05 21:53:17.515625 [DVB EPG timer(13)]: RunGraph
2012-10-05 21:53:17.531250 [DVB EPG timer(13)]: subch:0 OnGraphStart
2012-10-05 21:53:17.531250 [DVB EPG timer(13)]: dvb: RunGraph
2012-10-05 21:53:18.093750 [DVB EPG timer(13)]: dvb: LockInOnSignal ok
2012-10-05 21:53:18.093750 [DVB EPG timer(13)]: subch:0 OnGraphStarted
2012-10-05 21:53:18.109375 [DVB EPG timer(13)]: subch:0 SetupPmtGrabberid 66 sid:4E27
2012-10-05 21:53:18.109375 [DVB EPG timer(13)]: subch:0 set pmt grabber pmt:66 sid:4E27
2012-10-05 21:53:18.109375 [DVB EPG timer(13)]: TimeShifter.OnAfterTune: resetting audio/video time
2012-10-05 21:53:18.109375 [DVB EPG timer(13)]: WaitForPMT: Waiting for PMT 66
2012-10-05 21:53:18.218750 [(16)]: subch:0 OnPMTReceived() pmt:66 ran:True dynamic:False
2012-10-05 21:53:18.218750 [DVB EPG timer(13)]: WaitForPMT: Found PMT after 0,109375 seconds.
2012-10-05 21:53:18.218750 [DVB EPG timer(13)]: subch:0 SendPmt:4E27 4E27 FFFFFFFF F
2012-10-05 21:53:18.218750 [DVB EPG timer(13)]: Decode pmt
2012-10-05 21:53:18.234375 [DVB EPG timer(13)]: descr1 len:8 9 6 17 2 f7 c8 0 c8
2012-10-05 21:53:18.234375 [DVB EPG timer(13)]: descr1 len:6 9 4 18 33 f8 c8
2012-10-05 21:53:18.234375 [DVB EPG timer(13)]: descr1 len:6 9 4 9 c4 fb c8
2012-10-05 21:53:18.234375 [DVB EPG timer(13)]: descr1 len:6 9 4 9 8c fa c8
2012-10-05 21:53:18.234375 [DVB EPG timer(13)]: descr1 len:6 9 4 d 5 ff c8
2012-10-05 21:53:18.265625 [DVB EPG timer(13)]: descr1 len:6 9 4 d 95 ff c9
2012-10-05 21:53:18.265625 [DVB EPG timer(13)]: descr1 len:6 9 4 6 48 ff ca
2012-10-05 21:53:18.265625 [DVB EPG timer(13)]: Set descriptor data with length 3
2012-10-05 21:53:18.265625 [DVB EPG timer(13)]: PROBLEM : descriptor lengths dont match 7 10
2012-10-05 21:53:18.281250 [DVB EPG timer(13)]: Set descriptor data with length 3
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: Set descriptor data with length 6
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: PROBLEM : descriptor lengths dont match 3 9
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: subch:0 SendPMT version:15 len:107 20007
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: TechnoTrend: slot 0 changed
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: TechnoTrend: CI statuslotModuleOk
2012-10-05 21:53:18.296875 [DVB EPG timer(13)]: TechnoTrend: CI text :TechniCrypt B2C
2012-10-05 21:53:18.312500 [DVB EPG timer(13)]: TechnoTrend: ca system id 05
2012-10-05 21:53:18.312500 [DVB EPG timer(13)]: TechnoTrend: DescrambleMultiple1)
2012-10-05 21:53:18.312500 [DVB EPG timer(13)]: TechnoTrend: DescrambleMultiple: serviceId:20007
2012-10-05 21:53:18.312500 [DVB EPG timer(13)]: $ OnCaChange slot:255 reply:E status:0
2012-10-05 21:53:18.343750 [DVB EPG timer(13)]: $ CI: SetProgram OK
2012-10-05 21:53:18.468750 [DVB EPG timer(13)]: $ OnCaChange slot:255 reply:E status:0
2012-10-05 21:53:18.468750 [DVB EPG timer(13)]: $ CI: SetProgram OK
2012-10-05 21:53:18.468750 [DVB EPG timer(13)]: TechnoTrend: services decodeduccess 1
2012-10-05 21:53:18.468750 [DVB EPG timer(13)]: TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:True
2012-10-05 21:53:18.484375 [DVB EPG timer(13)]: subch:0 cam flags:True
2012-10-05 21:53:18.484375 [DVB EPG timer(13)]: subch:0 SetMpegPidMapping
2012-10-05 21:53:18.500000 [DVB EPG timer(13)]: subch:0 pid:6FF pcr
2012-10-05 21:53:18.500000 [DVB EPG timer(13)]: subch:0 pid:66 pmt
2012-10-05 21:53:18.515625 [DVB EPG timer(13)]: subch:0 pid:27 teletext type:6
2012-10-05 21:53:18.515625 [DVB EPG timer(13)]: subch:0 map pid:27 teletext type:6
2012-10-05 21:53:18.515625 [DVB EPG timer(13)]: subch:0 pid:6FF video type:MPEG-2
2012-10-05 21:53:18.546875 [DVB EPG timer(13)]: subch:0 map pid:6FF video type:MPEG-2
2012-10-05 21:53:18.546875 [DVB EPG timer(13)]: subch:0 pid:700 audio lang:deu type:MPEG-1
2012-10-05 21:53:18.546875 [DVB EPG timer(13)]: subch:0 map pid:700 audio lang:deu type:MPEG-1
2012-10-05 21:53:18.562500 [DVB EPG timer(13)]: subch:0 pid:705 type:5
2012-10-05 21:53:18.578125 [DVB EPG timer(13)]: OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
2012-10-05 21:53:18.578125 [DVB EPG timer(13)]: subch:0 stop tif
2012-10-05 21:53:18.578125 [DVB EPG timer(13)]: WaitForPmt: PMT handling took 0,359375 seconds.
2012-10-05 21:53:18.656250 [DVB EPG timer(13)]: card: Tuner locked: True
2012-10-05 21:53:18.656250 [DVB EPG timer(13)]: **************************************************
2012-10-05 21:53:18.656250 [DVB EPG timer(13)]: ***** SIGNAL LEVEL: 72, SIGNAL QUALITY: 100 *****
2012-10-05 21:53:18.656250 [DVB EPG timer(13)]: **************************************************
2012-10-05 21:53:18.671875 [DVB EPG timer(13)]: card: tuned user: epg subchannel: 0
2012-10-05 21:53:18.671875 [DVB EPG timer(13)]: user:epg add
2012-10-05 21:53:18.671875 [DVB EPG timer(13)]: CardReservation.RemoveTuneTicket: removed reservation with id=17, tuningdetails=DVBS:tvroSiebenSat.1 PULS 4 Austria Freq:12051000 ONID:1 TSID:1082 SID:20007 PMT:0x66 FTA:False LCN:446 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-10-05 21:53:18.671875 [DVB EPG timer(13)]: card: SignalTuneEvent card: 3 / subch: 0
2012-10-05 21:53:18.703125 [DVB EPG timer(13)]: Controller: GrabEpg on card ID == 3
2012-10-05 21:53:18.734375 [DVB EPG timer(13)]: dvb:grab epg...
2012-10-05 21:58:19.453125 [(13)]: Controller: AbortEPGGrabbing on card ID == 3
2012-10-05 21:58:19.484375 [(13)]: dvb:abort grabbing epg
2012-10-05 21:58:19.734375 [(15)]: TechnoTrend: slot 0 changed[/collapse]

So the CAM is okay for descrambling... then "suddenly" 5 minutes later we have a CI slot change message. After this, the CAM seems to not respond properly:

2012-10-05 22:04:49.640625 [DVB EPG timer(9)]: TechnoTrend: slot 0 changed
2012-10-05 22:04:49.640625 [DVB EPG timer(9)]: TechnoTrend: DescrambleMultiple1)
2012-10-05 22:04:49.656250 [DVB EPG timer(9)]: TechnoTrend: DescrambleMultiple: serviceId:13221
2012-10-05 22:04:49.671875 [DVB EPG timer(9)]: TechnoTrend: CI module inserted but not yet ready
2012-10-05 22:04:49.671875 [DVB EPG timer(9)]: TechnoTrend IsCamReady(): IsCamPresent:True, IsCamReady:False

I guess you did not touch the CAM or the smartcard, so this is also strange.

To be clear there are two problems, both related to the TT tuner:

1. TV Server crash
2. CAM becomes unavailable for unknown reason

***The DVB-T tuner does not seem to have any problems at all.***

To speculate...
The first problem is almost certainly related to the TV Server graph handling. The TT tuner doesn't like what TV Server is asking it to do for some reason.
The second problem could be a compatibility issue between your CAM and the TT tuner.

I would be happy to get a MP version without these start / restart problems for DVB-S and DVB-T, because there is also no tv at the moment.

I will PM you with a link to an installer.

mm