MediaPortal Version: 1.15.0
Description
I've just added a CAM to my Technotrend c-1501 on a well-working system (w10, asus motherboard, i3) with all drivers up-to-date, but it fails both to render an encrypted channel as well as open the CI-menu in server configuration. Below is what's in the log on debug level when this happens.
/Peter
[2017-01-21 16:34:50,659] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityEPG : 1
[2017-01-21 16:34:50,674] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityUser : 2
[2017-01-21 16:34:50,674] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityScheduler : 100
[2017-01-21 16:34:50,674] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:50,674] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:50,910] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:50,911] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:50,913] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:50,914] [Log ] [12 ] [INFO ] - Controller: card:2 type
vbIP cannot tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC can tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC users: 0
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 277 msec
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC is available
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 283 msec
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV 3 133
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:2 type
vbIP cannot tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC can tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC users: 0
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 2 msec
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC is available
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 3 msec
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - CiMenuSupported called cardid 4
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - CiMenuSupported card TechnoTrend BDA/DVB-C Tuner supported: False
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - RemoteControl: RegisterChannel first called in Domain TVService.exe for thread with id 12
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: StartTimeShifting TV 3 133
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: epg stop
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:2 type
vbIP cannot tune to channel
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC can tune to channel
[2017-01-21 16:34:54,043] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:54,044] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 9 msec
[2017-01-21 16:34:54,045] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:54,046] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 12 msec
[2017-01-21 16:34:54,078] [Log ] [12 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1, tuningdetails=DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC users: 0
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: card:4 type
vbC is available
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
[2017-01-21 16:34:54,078] [Log ] [12 ] [DEBUG] - CardReservationBase: tvcard=4, user=serv1, dbChannel=133, ticket=1, tunestate=Tuning, stopstate=Idle
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - card: CardTune 4 TV 3 serv1:4:-1
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - card: Tune on card 4 to subchannel TV 3
[2017-01-21 16:34:54,094] [Log ] [12 ] [DEBUG] - card: user: serv1:4:-1 tune DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,094] [Log ] [12 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - dvbc: Tune
VBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:BuildGraph
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:AddNetworkProviderFilter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:AddNetworkProviderFilter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:Add Generic Network Provider
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb: Add Mediaportal TsWriter filter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:CreateTuningSpace()
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:Found correct tuningspace MediaPortal DVBC TuningSpace
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:Add MPEG2 Demultiplexer filter
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb:AddAndConnectBDABoardFilters
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: find bda tuner
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: using [Tuner]: TechnoTrend BDA/DVB-C Tuner
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: Render [Network provider]->[Tuner] OK
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Tuner filter
[2017-01-21 16:34:54,143] [Log ] [12 ] [INFO ] - dvb: Find BDA receiver
[2017-01-21 16:34:54,144] [Log ] [12 ] [INFO ] - dvb: match Capture by Tuner device path
[2017-01-21 16:34:54,145] [Log ] [12 ] [INFO ] - dvb: -TechnoTrend BDA/DVB Capture
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render [Tuner]->[Capture] AOK
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Capture device
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: WinTv CI module not detected.
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb:add Inf Tee filter
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render ...->[inftee]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Inf Tee
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render [inftee]->[demux]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: AddTransportStreamFiltersToGraph
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - add BDA MPEG2 Transport Information Filter filter
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - pinTif:name:IB Input [3/0] Direction:Input Connected:False
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - Connect tif and mpeg2 sections and tables
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb:try tif:name:001 [5/0] Direction:Output Connected:False
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - tif connected
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render ..->[TsWriter]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Checking for hardware specific extensions
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - CAM is Default model
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for KNC
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - KNC: IsKNC False
[2017-01-21 16:34:54,162] [Log ] [12 ] [DEBUG] - KNC: Disable CI
[2017-01-21 16:34:54,162] [Log ] [12 ] [DEBUG] - KNC: Disposing CI handler
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for Digital Everywhere
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for Twinhan
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Twinhan: CI detection finished
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for TechnoTrend
[2017-01-21 16:34:54,178] [Log ] [12 ] [DEBUG] - TechnoTrend: initalized id:23, driver version:5.0.1.8
[2017-01-21 16:34:54,178] [Log ] [12 ] [DEBUG] - TechnoTrend: OpenCI succeeded
[2017-01-21 16:34:54,178] [Log ] [12 ] [INFO ] - TechnoTrend card detected
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb: GetTunerSignalStatistics()
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb:GetNewSubChannel:0 #0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - TvDvbChannel ctor new subchIndex:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
ubmiting tunerequest Channel:TV 3 subChannel:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb:using existing subchannel:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
ubmit tunerequest size:1 new:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnBeforeTune
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
ubmit tunerequest calling put_TuneRequest
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
ubmit tunerequest done calling put_TuneRequest
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnAfterTune
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - RunGraph
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnGraphStart
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb: RunGraph
[2017-01-21 16:34:55,198] [Log ] [12 ] [INFO ] - dvb: LockInOnSignal ok
[2017-01-21 16:34:55,198] [Log ] [12 ] [INFO ] - subch:0 OnGraphStarted
[2017-01-21 16:34:55,214] [Log ] [12 ] [INFO ] - subch:0 SetupPmtGrabber
id 440 sid:8C
[2017-01-21 16:34:55,214] [Log ] [12 ] [INFO ] - subch:0 set pmt grabber pmt:440 sid:8C
[2017-01-21 16:34:55,214] [Log ] [12 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2017-01-21 16:34:55,214] [Log ] [12 ] [DEBUG] - WaitForPMT: Waiting for PMT 440
[2017-01-21 16:34:55,283] [Log ] [18 ] [INFO ] - subch:0 OnPMTReceived() pmt:440 ran:True dynamic:False
[2017-01-21 16:34:55,283] [Log ] [12 ] [DEBUG] - WaitForPMT: Found PMT after 0,0689554 seconds.
[2017-01-21 16:34:55,299] [Log ] [12 ] [INFO ] - subch:0 SendPmt:8C 8C FFFFFFFF C
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Decode pmt
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - descr1 len:6 9 4 4a ea e4 62
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 7
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - subch:0 SendPMT version:12 len:61 140
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple
1)
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:140
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: CI slot state unknown, allow one retry
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:False, IsCamReady:False
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - subch:0 SendPmt failed cam flags:False
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - WaitForPMT: waiting for SendPmtToCam 84,665 ms.
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 SendPmt:8C 8C FFFFFFFF C
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Decode pmt
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - descr1 len:6 9 4 4a ea e4 62
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 7
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 SendPMT version:12 len:61 140
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple
1)
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:140
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: CI slot state still unknown after one retry. Stop trying.
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:False, IsCamReady:False
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 cam flags:False
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 SetMpegPidMapping
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44A pcr
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:440 pmt
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44A video type:MPEG-2
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44A video type:MPEG-2
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44B audio lang:swe type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44B audio lang:swe type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44C audio lang:syn type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44D teletext type:6
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44D teletext type:6
[2017-01-21 16:34:58,345] [Log ] [12 ] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 stop tif
[2017-01-21 16:34:58,345] [Log ] [12 ] [DEBUG] - WaitForPmt: PMT handling took 3,0463208 seconds.
[2017-01-21 16:34:58,360] [Log ] [12 ] [DEBUG] - card: Tuner locked: True
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - **************************************************
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - **************************************************
[2017-01-21 16:34:58,360] [Log ] [12 ] [DEBUG] - card: tuned user: serv1 subchannel: 0
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - user:serv1 add
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - card2:serv1 4 0
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - Controller: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - Controller: epg stop
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: CAM enabled : True
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0 SetTimeShiftFileName:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - Set video / audio observer
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0 SetTimeShiftFileName fill in pids
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0-0 tswriter StartTimeshifting...
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card: WaitForFile - no audio was found after 15,0059862 seconds
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card: WaitForFile - audio and video stream is scrambled
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card TechnoTrend BDA/DVB-C Tuner: StopTimeShifting user:serv1 sub:0
[2017-01-21 16:35:13,382] [Log ] [12 ] [DEBUG] - card not IDLE - removing user: serv1
[2017-01-21 16:35:13,382] [Log ] [12 ] [DEBUG] - usermanagement.RemoveUser: serv1, subch: 0 of 1, card: 4
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - user:serv1 remove
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - subch:0-0 tswriter StopTimeshifting...
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - DVB subch:0 Decompose()
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2017-01-21 16:35:13,415] [Log ] [12 ] [INFO ] - dvb
topGraph called
[2017-01-21 16:35:13,415] [Log ] [12 ] [INFO ] - tvcard:FreeAllSubChannels
[2017-01-21 16:35:13,416] [Log ] [12 ] [INFO ] - dvb
topGraph
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - debug: IMediaControl stopped! hr = 0x0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - dvb
topGraph called
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - tvcard:FreeAllSubChannels
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - dvb
topGraph filterstate already stopped, returning.
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - user:serv1 remove
[2017-01-21 16:35:13,420] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:35:13,420] [Log ] [12 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=1, tuningdetails=DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - card: SignalTuneEvent card: 4 / subch: 0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: serv1 4 0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: Timeshifting failed, no more cards available.
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: epg start
Steps to Reproduce:
Test 1: click on an encrypted channel in the guide
Test 2: click on open CI-menu in server configuration
Description
I've just added a CAM to my Technotrend c-1501 on a well-working system (w10, asus motherboard, i3) with all drivers up-to-date, but it fails both to render an encrypted channel as well as open the CI-menu in server configuration. Below is what's in the log on debug level when this happens.
/Peter
[2017-01-21 16:34:50,659] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityEPG : 1
[2017-01-21 16:34:50,674] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityUser : 2
[2017-01-21 16:34:50,674] [Log ] [12 ] [DEBUG] - UserFactory setting PriorityScheduler : 100
[2017-01-21 16:34:50,674] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:50,674] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:50,910] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:50,911] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:50,913] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:50,914] [Log ] [12 ] [INFO ] - Controller: card:2 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 277 msec
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 283 msec
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV 3 133
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:2 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,957] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 2 msec
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:50,973] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 3 msec
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - CiMenuSupported called cardid 4
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - CiMenuSupported card TechnoTrend BDA/DVB-C Tuner supported: False
[2017-01-21 16:34:50,973] [Log ] [12 ] [DEBUG] - RemoteControl: RegisterChannel first called in Domain TVService.exe for thread with id 12
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: StartTimeShifting TV 3 133
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: epg stop
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: find free card for channel TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: find card for channel TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: got 1 tuning details for TV 3
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: channel #1 DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:1 type:RadioWebStream cannot tune to channel
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:2 type
[2017-01-21 16:34:54,028] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:54,043] [Log ] [12 ] [INFO ] - Controller: found 1 card(s) for channel
[2017-01-21 16:34:54,044] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 9 msec
[2017-01-21 16:34:54,045] [Log ] [12 ] [INFO ] - Controller: found 1 free card(s)
[2017-01-21 16:34:54,046] [Log ] [12 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 12 msec
[2017-01-21 16:34:54,078] [Log ] [12 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1, tuningdetails=DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: card:4 type
[2017-01-21 16:34:54,078] [Log ] [12 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
[2017-01-21 16:34:54,078] [Log ] [12 ] [DEBUG] - CardReservationBase: tvcard=4, user=serv1, dbChannel=133, ticket=1, tunestate=Tuning, stopstate=Idle
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - card: CardTune 4 TV 3 serv1:4:-1
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - card: Tune on card 4 to subchannel TV 3
[2017-01-21 16:34:54,094] [Log ] [12 ] [DEBUG] - card: user: serv1:4:-1 tune DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:34:54,094] [Log ] [12 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
[2017-01-21 16:34:54,094] [Log ] [12 ] [INFO ] - dvbc: Tune
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:BuildGraph
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:AddNetworkProviderFilter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:AddNetworkProviderFilter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:Add Generic Network Provider
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb: Add Mediaportal TsWriter filter
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:CreateTuningSpace()
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvbc:Found correct tuningspace MediaPortal DVBC TuningSpace
[2017-01-21 16:34:54,109] [Log ] [12 ] [INFO ] - dvb:Add MPEG2 Demultiplexer filter
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb:AddAndConnectBDABoardFilters
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: find bda tuner
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: using [Tuner]: TechnoTrend BDA/DVB-C Tuner
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: Render [Network provider]->[Tuner] OK
[2017-01-21 16:34:54,125] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Tuner filter
[2017-01-21 16:34:54,143] [Log ] [12 ] [INFO ] - dvb: Find BDA receiver
[2017-01-21 16:34:54,144] [Log ] [12 ] [INFO ] - dvb: match Capture by Tuner device path
[2017-01-21 16:34:54,145] [Log ] [12 ] [INFO ] - dvb: -TechnoTrend BDA/DVB Capture
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render [Tuner]->[Capture] AOK
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Capture device
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: WinTv CI module not detected.
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb:add Inf Tee filter
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render ...->[inftee]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Setting lastFilter to Inf Tee
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render [inftee]->[demux]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: AddTransportStreamFiltersToGraph
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - add BDA MPEG2 Transport Information Filter filter
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - pinTif:name:IB Input [3/0] Direction:Input Connected:False
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - Connect tif and mpeg2 sections and tables
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb:try tif:name:001 [5/0] Direction:Output Connected:False
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - tif connected
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Render ..->[TsWriter]
[2017-01-21 16:34:54,147] [Log ] [12 ] [INFO ] - dvb: Checking for hardware specific extensions
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - CAM is Default model
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for KNC
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - KNC: IsKNC False
[2017-01-21 16:34:54,162] [Log ] [12 ] [DEBUG] - KNC: Disable CI
[2017-01-21 16:34:54,162] [Log ] [12 ] [DEBUG] - KNC: Disposing CI handler
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for Digital Everywhere
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for Twinhan
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Twinhan: CI detection finished
[2017-01-21 16:34:54,162] [Log ] [12 ] [INFO ] - Check for TechnoTrend
[2017-01-21 16:34:54,178] [Log ] [12 ] [DEBUG] - TechnoTrend: initalized id:23, driver version:5.0.1.8
[2017-01-21 16:34:54,178] [Log ] [12 ] [DEBUG] - TechnoTrend: OpenCI succeeded
[2017-01-21 16:34:54,178] [Log ] [12 ] [INFO ] - TechnoTrend card detected
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb: GetTunerSignalStatistics()
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb:GetNewSubChannel:0 #0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - TvDvbChannel ctor new subchIndex:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb:using existing subchannel:0
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnBeforeTune
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnAfterTune
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - RunGraph
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - subch:0 OnGraphStart
[2017-01-21 16:34:54,194] [Log ] [12 ] [INFO ] - dvb: RunGraph
[2017-01-21 16:34:55,198] [Log ] [12 ] [INFO ] - dvb: LockInOnSignal ok
[2017-01-21 16:34:55,198] [Log ] [12 ] [INFO ] - subch:0 OnGraphStarted
[2017-01-21 16:34:55,214] [Log ] [12 ] [INFO ] - subch:0 SetupPmtGrabber
[2017-01-21 16:34:55,214] [Log ] [12 ] [INFO ] - subch:0 set pmt grabber pmt:440 sid:8C
[2017-01-21 16:34:55,214] [Log ] [12 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
[2017-01-21 16:34:55,214] [Log ] [12 ] [DEBUG] - WaitForPMT: Waiting for PMT 440
[2017-01-21 16:34:55,283] [Log ] [18 ] [INFO ] - subch:0 OnPMTReceived() pmt:440 ran:True dynamic:False
[2017-01-21 16:34:55,283] [Log ] [12 ] [DEBUG] - WaitForPMT: Found PMT after 0,0689554 seconds.
[2017-01-21 16:34:55,299] [Log ] [12 ] [INFO ] - subch:0 SendPmt:8C 8C FFFFFFFF C
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Decode pmt
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - descr1 len:6 9 4 4a ea e4 62
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - Set descriptor data with length 7
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - subch:0 SendPMT version:12 len:61 140
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:140
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - TechnoTrend: CI slot state unknown, allow one retry
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:False, IsCamReady:False
[2017-01-21 16:34:55,314] [Log ] [12 ] [INFO ] - subch:0 SendPmt failed cam flags:False
[2017-01-21 16:34:55,314] [Log ] [12 ] [DEBUG] - WaitForPMT: waiting for SendPmtToCam 84,665 ms.
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 SendPmt:8C 8C FFFFFFFF C
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Decode pmt
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - descr1 len:6 9 4 4a ea e4 62
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 6
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - Set descriptor data with length 7
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 SendPMT version:12 len:61 140
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: slot 0 changed
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: DescrambleMultiple: serviceId:140
[2017-01-21 16:34:58,329] [Log ] [12 ] [DEBUG] - TechnoTrend: CI slot state still unknown after one retry. Stop trying.
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - TechnoTrend IsCamReady(): IsCamPresent:False, IsCamReady:False
[2017-01-21 16:34:58,329] [Log ] [12 ] [INFO ] - subch:0 cam flags:False
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 SetMpegPidMapping
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44A pcr
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:440 pmt
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44A video type:MPEG-2
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44A video type:MPEG-2
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44B audio lang:swe type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44B audio lang:swe type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44C audio lang:syn type:MPEG-1
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 pid:44D teletext type:6
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 map pid:44D teletext type:6
[2017-01-21 16:34:58,345] [Log ] [12 ] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
[2017-01-21 16:34:58,345] [Log ] [12 ] [INFO ] - subch:0 stop tif
[2017-01-21 16:34:58,345] [Log ] [12 ] [DEBUG] - WaitForPmt: PMT handling took 3,0463208 seconds.
[2017-01-21 16:34:58,360] [Log ] [12 ] [DEBUG] - card: Tuner locked: True
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - **************************************************
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - **************************************************
[2017-01-21 16:34:58,360] [Log ] [12 ] [DEBUG] - card: tuned user: serv1 subchannel: 0
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - user:serv1 add
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - card2:serv1 4 0
[2017-01-21 16:34:58,360] [Log ] [12 ] [INFO ] - Controller: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - Controller: epg stop
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: CAM enabled : True
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0 SetTimeShiftFileName:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - Set video / audio observer
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0 SetTimeShiftFileName fill in pids
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - subch:0-0 tswriter StartTimeshifting...
[2017-01-21 16:34:58,376] [Log ] [12 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card: WaitForFile - no audio was found after 15,0059862 seconds
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card: WaitForFile - audio and video stream is scrambled
[2017-01-21 16:35:13,382] [Log ] [12 ] [INFO ] - card TechnoTrend BDA/DVB-C Tuner: StopTimeShifting user:serv1 sub:0
[2017-01-21 16:35:13,382] [Log ] [12 ] [DEBUG] - card not IDLE - removing user: serv1
[2017-01-21 16:35:13,382] [Log ] [12 ] [DEBUG] - usermanagement.RemoveUser: serv1, subch: 0 of 1, card: 4
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - user:serv1 remove
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - subch:0-0 tswriter StopTimeshifting...
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - DVB subch:0 Decompose()
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2017-01-21 16:35:13,398] [Log ] [12 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2017-01-21 16:35:13,415] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:35:13,415] [Log ] [12 ] [INFO ] - tvcard:FreeAllSubChannels
[2017-01-21 16:35:13,416] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - debug: IMediaControl stopped! hr = 0x0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - tvcard:FreeAllSubChannels
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - dvb
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - user:serv1 remove
[2017-01-21 16:35:13,420] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
[2017-01-21 16:35:13,420] [Log ] [12 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=1, tuningdetails=DVBC:tv:Transit TV 3 Freq:306000 ONID:41001 TSID:1 SID:140 PMT:0x440 FTA:False LCN:3 SymbolRate:6875 Modulation:Mod256Qam
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - card: SignalTuneEvent card: 4 / subch: 0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: serv1 4 0
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: Timeshifting failed, no more cards available.
[2017-01-21 16:35:13,420] [Log ] [12 ] [INFO ] - Controller: epg start
Steps to Reproduce:
Test 1: click on an encrypted channel in the guide
Test 2: click on open CI-menu in server configuration