Menu ▾ ▴

MEdiaportal+Mdapi plus+diseqc switch

General Discussion
PlusPlus
2016-01-28
2016-03-20

  • Berra Bus

    Berra Bus - 2016-01-28

    Hi! I have a small problem and im not sure its related to mdapi plus but it might be. When changing channels between differnet satellites it stops to work and i have to restart tv server to get it working again. For example. only channel 6 is dvb2. All others are dvb1 in thsi example. Switching from 3 to 4 to 5 to 6 works fine, switching back to 5, 4, 3 also works but if i go to 12 or 8 or 9 i first get cant start timeshifting. If i go to 4 or 5 again i maybe get NO SIGNAL but channel 6 works when trying it again. Its like it gets stuck at dvb2 and only tvserver restart solves the problem. I thought it might be mdapi that get stuck...

    LOG

    [2016-01-28 19:06:10,158] [Log ] [27 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:06:10,158] [Log ] [27 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:06:10,158] [Log ] [27 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:06:10,158] [Log ] [27 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,158] [Log ] [27 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:10,174] [Log ] [27 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:10,174] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:10,174] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:10,174] [Log ] [27 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:10,174] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 24 msec
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 35 msec
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV3 HD 3505
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:06:10,189] [Log ] [27 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:06:10,205] [Log ] [27 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:06:10,205] [Log ] [27 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,205] [Log ] [27 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:10,205] [Log ] [27 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:10,205] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 23 msec
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:10,220] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 34 msec
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - CiMenuSupported called cardid 4
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - CiMenuSupported card TBS 6982 DVBS/S2 Tuner B supported: False
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:10,236] [Log ] [27 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:10,252] [Log ] [27 ] [INFO ] - Controller: StartTimeShifting TV3 HD 3505
    [2016-01-28 19:06:10,252] [Log ] [27 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:10,252] [Log ] [27 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:06:10,252] [Log ] [27 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:06:10,252] [Log ] [27 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:06:10,267] [Log ] [27 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,267] [Log ] [27 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:10,267] [Log ] [27 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:10,267] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:10,267] [Log ] [27 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:10,283] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 20 msec
    [2016-01-28 19:06:10,283] [Log ] [27 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:10,283] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 28 msec
    [2016-01-28 19:06:10,283] [Log ] [27 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=3, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,283] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:10,299] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:10,299] [Log ] [27 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:06:10,299] [Log ] [27 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:06:10,299] [Log ] [27 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3505, ticket=3, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:06:10,299] [Log ] [27 ] [INFO ] - card: CardTune 4 TV3 HD (S) Hometown:4:-1
    [2016-01-28 19:06:10,314] [Log ] [27 ] [INFO ] - card: Tune on card 4 to subchannel TV3 HD (S)
    [2016-01-28 19:06:10,314] [Log ] [27 ] [DEBUG] - card: user: Hometown:4:-1 tune DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,314] [Log ] [27 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:06:10,314] [Log ] [27 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - dvb:GetNewSubChannel:0 #0
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - TvDvbChannel ctor new subchIndex:0
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:06:10,330] [Log ] [27 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:06:10,345] [Log ] [27 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:06:10,345] [Log ] [27 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:06:10,345] [Log ] [27 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:06:10,345] [Log ] [27 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:06:10,361] [Log ] [27 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:06:10,470] [Log ] [27 ] [INFO ] - dvb:Submiting tunerequest Channel:TV3 HD (S) subChannel:0
    [2016-01-28 19:06:10,470] [Log ] [27 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:06:10,470] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:06:10,470] [Log ] [27 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:06:10,486] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:06:10,486] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:06:10,486] [Log ] [27 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:06:10,486] [Log ] [27 ] [INFO ] - RunGraph
    [2016-01-28 19:06:10,486] [Log ] [27 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:06:10,502] [Log ] [27 ] [INFO ] - dvb: RunGraph
    [2016-01-28 19:06:10,736] [Log ] [27 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:06:10,752] [Log ] [27 ] [INFO ] - subch:0 OnGraphStarted
    [2016-01-28 19:06:10,752] [Log ] [27 ] [INFO ] - subch:0 SetupPmtGrabber:pid 18A sid:115E
    [2016-01-28 19:06:10,752] [Log ] [27 ] [INFO ] - subch:0 set pmt grabber pmt:18A sid:115E
    [2016-01-28 19:06:10,752] [Log ] [27 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:06:10,752] [Log ] [27 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:06:10,767] [Log ] [27 ] [DEBUG] - WaitForPMT: Waiting for PMT 18A
    [2016-01-28 19:06:10,908] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:18A ran:True dynamic:False
    [2016-01-28 19:06:10,908] [Log ] [27 ] [DEBUG] - WaitForPMT: Found PMT after 0,140624 seconds.
    [2016-01-28 19:06:11,158] [Log ] [29 ] [INFO ] - subch:OnCaReceived()
    [2016-01-28 19:06:11,158] [Log ] [27 ] [INFO ] - subch:0 SendPmt:CA found after 0,2343752 seconds
    [2016-01-28 19:06:11,158] [Log ] [27 ] [INFO ] - subch:0 SendPmt:115E 115E FFFFFFFF 1C
    [2016-01-28 19:06:11,174] [Log ] [27 ] [INFO ] - Decode pmt
    [2016-01-28 19:06:11,174] [Log ] [27 ] [INFO ] - descr1 len:6 9 4 b 0 fb 76
    [2016-01-28 19:06:11,174] [Log ] [27 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:06:11,174] [Log ] [27 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:06:11,189] [Log ] [27 ] [INFO ] - subch:0 SendPMT version:28 len:53 4446
    [2016-01-28 19:06:11,189] [Log ] [27 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:06:11,189] [Log ] [27 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:06:11,189] [Log ] [27 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:11,205] [Log ] [27 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:11,205] [Log ] [27 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:06:11,205] [Log ] [27 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:06:11,205] [Log ] [27 ] [INFO ] - subch:0 pid:819 pcr
    [2016-01-28 19:06:11,205] [Log ] [27 ] [INFO ] - subch:0 pid:18A pmt
    [2016-01-28 19:06:11,205] [Log ] [27 ] [INFO ] - subch:0 pid:18BD teletext type:6
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - subch:0 map pid:18BD teletext type:6
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - subch:0 pid:819 video type:H.264
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - subch:0 map pid:819 video type:H.264
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - subch:0 pid:D14 audio lang:swe type:AC3
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - subch:0 map pid:D14 audio lang:swe type:AC3
    [2016-01-28 19:06:11,220] [Log ] [27 ] [INFO ] - ecm len:6 9 4 B 0 FB 76
    [2016-01-28 19:06:11,236] [Log ] [27 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:11,236] [Log ] [27 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :11
    [2016-01-28 19:06:11,236] [Log ] [27 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:06:11,236] [Log ] [27 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'TV3 HD (S)' using plugin slot 1 of 1 avail.
    [2016-01-28 19:06:11,236] [Log ] [27 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:11,252] [Log ] [27 ] [INFO ] - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    [2016-01-28 19:06:11,252] [Log ] [27 ] [INFO ] - ecm len:6 9 4 B 0 FB 76
    [2016-01-28 19:06:11,252] [Log ] [27 ] [INFO ] - ECM #0 CA:0xB00 ECM:0x1B76 ID:0x0
    [2016-01-28 19:06:11,252] [Log ] [27 ] [INFO ] - mdplug: tp_id:24(0x18) sid:4446(0x115E) pmt_id:394(0x18A)
    [2016-01-28 19:06:11,252] [Log ] [27 ] [INFO ] - mdplug: #0 CA_typ:2816(0xB00) ECM:7030(0x1B76) EMM:0x30 provider:0(0x0)
    [2016-01-28 19:06:11,314] [Log ] [27 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7030(0x1B76)
    [2016-01-28 19:06:11,314] [Log ] [27 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:06:11,314] [Log ] [27 ] [DEBUG] - WaitForPmt: PMT handling took 0,3906252 seconds.
    [2016-01-28 19:06:11,330] [Log ] [27 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:06:11,330] [Log ] [27 ] [INFO ] - klzzwxh:11437klzzwxh:11436klzzwxh:11435klzzwxh:11434klzzwxh:11433klzzwxh:11432klzzwxh:11431
    klzzwxh:10792 klzzwxh:10793 klzzwxh:10794 klzzwxh:10795 - ** SIGNAL LEVEL: 94, SIGNAL QUALITY: 82
    klzzwxh:10807 klzzwxh:10808 klzzwxh:10809 klzzwxh:10810 - klzzwxh:11430klzzwxh:11429klzzwxh:11428klzzwxh:11427klzzwxh:11426klzzwxh:11425klzzwxh:11424
    klzzwxh:10815 klzzwxh:10816 klzzwxh:10817 klzzwxh:10818 - card: tuned user: Hometown subchannel: 0
    klzzwxh:10819 klzzwxh:10820 klzzwxh:10821 klzzwxh:10822 - user:Hometown add
    klzzwxh:10823 klzzwxh:10824 klzzwxh:10825 klzzwxh:10826 - card2:Hometown 4 0
    klzzwxh:10827 klzzwxh:10828 klzzwxh:10829 klzzwxh:10830 - Controller: delete timeshift files C:klzzwxh:10831rogramDataklzzwxh:10832eam MediaPortalklzzwxh:10833ediaPortal TV Serverklzzwxh:10834imeshiftbufferklzzwxh:10835ive4-0.ts
    klzzwxh:10836 klzzwxh:10837 klzzwxh:10838 klzzwxh:10839 - Timeshifting started - Recordings=0 TimeShiftingActive=True
    klzzwxh:10840 klzzwxh:10841 klzzwxh:10842 klzzwxh:10843 - TVServerKodi: OnTvServerEvent: StartTimeShifting
    klzzwxh:10844 klzzwxh:10845 klzzwxh:10846 klzzwxh:10847 - Controller: epg stop
    klzzwxh:10848 klzzwxh:10849 klzzwxh:10850 klzzwxh:10851 - card: StartTimeShifting 4 C:klzzwxh:10852rogramDataklzzwxh:10853eam MediaPortalklzzwxh:10854ediaPortal TV Serverklzzwxh:10855imeshiftbufferklzzwxh:10856ive4-0.ts
    klzzwxh:10857 klzzwxh:10858 klzzwxh:10859 klzzwxh:10860 - card: CAM enabled : True
    klzzwxh:10861 klzzwxh:10862 klzzwxh:10863 klzzwxh:10864 - subch:0 SetTimeShiftFileName:C:klzzwxh:10865rogramDataklzzwxh:10866eam MediaPortalklzzwxh:10867ediaPortal TV Serverklzzwxh:10868imeshiftbufferklzzwxh:10869ive4-0.ts
    klzzwxh:10870 klzzwxh:10871 klzzwxh:10872 klzzwxh:10873 - Set video / audio observer
    klzzwxh:10874 klzzwxh:10875 klzzwxh:10876 klzzwxh:10877 - subch:0 SetTimeShiftFileName fill in pids
    klzzwxh:10878 klzzwxh:10879 klzzwxh:10880 klzzwxh:10881 - subch:0-0 tswriter StartTimeshifting...
    klzzwxh:10882 klzzwxh:10883 klzzwxh:10884 klzzwxh:10885 - card: WaitForFile - waiting _eventAudio & _eventVideo
    klzzwxh:10886 klzzwxh:10887 klzzwxh:10888 klzzwxh:10889 - PID seen - type = Video
    klzzwxh:10890 klzzwxh:10891 klzzwxh:10892 klzzwxh:10893 - audioVideoEventHandler Video
    klzzwxh:10894 klzzwxh:10895 klzzwxh:10896 klzzwxh:10897 - PID seen - type = Audio
    klzzwxh:10898 klzzwxh:10899 klzzwxh:10900 klzzwxh:10901 - audioVideoEventHandler Audio
    klzzwxh:10902 klzzwxh:10903 klzzwxh:10904 klzzwxh:10905 - card: WaitForFile - video and audio are seen after 2,3437558 seconds
    klzzwxh:10906 klzzwxh:10907 klzzwxh:10908 klzzwxh:10909 - user:Hometown card:4 sub:0 add stream:C:klzzwxh:10910rogramDataklzzwxh:10911eam MediaPortalklzzwxh:10912ediaPortal TV Serverklzzwxh:10913imeshiftbufferklzzwxh:10914ive4-0.ts.tsbuffer
    klzzwxh:10915 klzzwxh:10916 klzzwxh:10917 klzzwxh:10918 - RTSP: add stream stream4.0 file:C:klzzwxh:10919rogramDataklzzwxh:10920eam MediaPortalklzzwxh:10921ediaPortal TV Serverklzzwxh:10922imeshiftbufferklzzwxh:10923ive4-0.ts.tsbuffer
    klzzwxh:10924 klzzwxh:10925 klzzwxh:10926 klzzwxh:10927 - Controller: StartTimeShifting started on card:4 to C:klzzwxh:10928rogramDataklzzwxh:10929eam MediaPortalklzzwxh:10930ediaPortal TV Serverklzzwxh:10931imeshiftbufferklzzwxh:10932ive4-0.ts.tsbuffer
    klzzwxh:10933 klzzwxh:10934 klzzwxh:10935 klzzwxh:10936 - CardReservation.RemoveTuneTicket: removed reservation with id=3, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    klzzwxh:10937 klzzwxh:10938 klzzwxh:10939 klzzwxh:10940 - card: SignalTuneEvent card: 4 / subch: 0
    klzzwxh:10941 klzzwxh:10942 klzzwxh:10943 klzzwxh:10944 - Controller: Hometown 4 0
    klzzwxh:10945 klzzwxh:10946 klzzwxh:10947 klzzwxh:10948 - TVServerKodi: OnTvServerEvent: EndZapChannel
    klzzwxh:10949 klzzwxh:10950 klzzwxh:10951 klzzwxh:10952 - control2:Hometown 4 0
    klzzwxh:10953 klzzwxh:10954 klzzwxh:10955 klzzwxh:10956 - Controller: DoSetChannelStates for 1033 channels
    klzzwxh:10957 klzzwxh:10958 klzzwxh:10959 klzzwxh:10960 - CiMenuSupported called cardid 4
    klzzwxh:10961 klzzwxh:10962 klzzwxh:10963 klzzwxh:10964 - Turbosight: is CAM ready
    klzzwxh:10965 klzzwxh:10966 klzzwxh:10967 klzzwxh:10968 - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    klzzwxh:10969 klzzwxh:10970 klzzwxh:10971 klzzwxh:10972 - Turbosight: interface not opened
    klzzwxh:10973 klzzwxh:10974 klzzwxh:10975 klzzwxh:10976 - CiMenuSupported card TBS 6982 DVBS/S2 Tuner B supported: False
    klzzwxh:10977 klzzwxh:10978 klzzwxh:10979 klzzwxh:10980 - Turbosight: is CAM ready
    klzzwxh:10981 klzzwxh:10982 klzzwxh:10983 klzzwxh:10984 - Turbosight: interface not opened
    klzzwxh:10985 klzzwxh:10986 klzzwxh:10987 klzzwxh:10988 - ChannelStates.DoSetChannelStates took 2171 msec
    klzzwxh:10989 klzzwxh:10990 klzzwxh:10991 klzzwxh:10992 - Controller: TimeShiftingWouldUseCard Sjuan 3135
    klzzwxh:10993 klzzwxh:10994 klzzwxh:10995 klzzwxh:10996 - Controller: find free card for channel Sjuan
    klzzwxh:10997 klzzwxh:10998 klzzwxh:10999 klzzwxh:11000 - Controller: find card for channel Sjuan
    klzzwxh:11001 klzzwxh:11002 klzzwxh:11003 klzzwxh:11004 - Controller: got 1 tuning details for Sjuan
    klzzwxh:11005 klzzwxh:11006 klzzwxh:11007 klzzwxh:11008 - Controller: channel #1 DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11009 klzzwxh:11010 klzzwxh:11011 klzzwxh:11012 - Controller: card:1 type:RadioWebStream is disabled
    klzzwxh:11013 klzzwxh:11014 klzzwxh:11015 klzzwxh:11016 - Controller: card:5 type:DvbS is disabled
    klzzwxh:11017 klzzwxh:11018 klzzwxh:11019 klzzwxh:11020 - Controller: card:4 type:DvbS can tune to channel
    klzzwxh:11021 klzzwxh:11022 klzzwxh:11023 klzzwxh:11024 - Controller: card:4 type:DvbS users: 0
    klzzwxh:11025 klzzwxh:11026 klzzwxh:11027 klzzwxh:11028 - Controller: found 1 card(s) for channel
    klzzwxh:11029 klzzwxh:11030 klzzwxh:11031 klzzwxh:11032 - AdvancedCardAllocation.GetAvailableCardsForChannel took 41 msec
    klzzwxh:11033 klzzwxh:11034 klzzwxh:11035 klzzwxh:11036 - Controller: card:4 type:DvbS is available
    klzzwxh:11037 klzzwxh:11038 klzzwxh:11039 klzzwxh:11040 - Controller: found 1 free card(s)
    klzzwxh:11041 klzzwxh:11042 klzzwxh:11043 klzzwxh:11044 - AdvancedCardAllocation.GetFreeCardsForChannel took 54 msec
    klzzwxh:11045 klzzwxh:11046 klzzwxh:11047 klzzwxh:11048 - Controller: StartTimeShifting Sjuan 3135
    klzzwxh:11049 klzzwxh:11050 klzzwxh:11051 klzzwxh:11052 - Controller: epg stop
    klzzwxh:11053 klzzwxh:11054 klzzwxh:11055 klzzwxh:11056 - Controller: find free card for channel Sjuan
    klzzwxh:11057 klzzwxh:11058 klzzwxh:11059 klzzwxh:11060 - Controller: find card for channel Sjuan
    klzzwxh:11061 klzzwxh:11062 klzzwxh:11063 klzzwxh:11064 - Controller: got 1 tuning details for Sjuan
    klzzwxh:11065 klzzwxh:11066 klzzwxh:11067 klzzwxh:11068 - Controller: channel #1 DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11069 klzzwxh:11070 klzzwxh:11071 klzzwxh:11072 - Controller: card:1 type:RadioWebStream is disabled
    klzzwxh:11073 klzzwxh:11074 klzzwxh:11075 klzzwxh:11076 - Controller: card:5 type:DvbS is disabled
    klzzwxh:11077 klzzwxh:11078 klzzwxh:11079 klzzwxh:11080 - Controller: card:4 type:DvbS can tune to channel
    klzzwxh:11081 klzzwxh:11082 klzzwxh:11083 klzzwxh:11084 - Controller: found 1 card(s) for channel
    klzzwxh:11085 klzzwxh:11086 klzzwxh:11087 klzzwxh:11088 - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    klzzwxh:11089 klzzwxh:11090 klzzwxh:11091 klzzwxh:11092 - Controller: found 1 free card(s)
    klzzwxh:11093 klzzwxh:11094 klzzwxh:11095 klzzwxh:11096 - AdvancedCardAllocation.GetFreeCardsForChannel took 31 msec
    klzzwxh:11097 klzzwxh:11098 klzzwxh:11099 klzzwxh:11100 - CardReservationBase.RequestCardTuneReservation: placed reservation with id=4, tuningdetails=DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11101 klzzwxh:11102 klzzwxh:11103 klzzwxh:11104 - Controller: card:4 type:DvbS users: 0
    klzzwxh:11105 klzzwxh:11106 klzzwxh:11107 klzzwxh:11108 - Controller: card:4 type:DvbS is available
    klzzwxh:11109 klzzwxh:11110 klzzwxh:11111 klzzwxh:11112 - Controller: try max 1 of 1 cards for timeshifting
    klzzwxh:11113 klzzwxh:11114 klzzwxh:11115 klzzwxh:11116 - TVServerKodi: OnTvServerEvent: StartZapChannel
    klzzwxh:11117 klzzwxh:11118 klzzwxh:11119 klzzwxh:11120 - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3135, ticket=4, tunestate=Tuning, stopstate=Idle
    klzzwxh:11121 klzzwxh:11122 klzzwxh:11123 klzzwxh:11124 - card: CardTune 4 Sjuan Hometown:4:-1
    klzzwxh:11125 klzzwxh:11126 klzzwxh:11127 klzzwxh:11128 - card: Tune on card 4 to subchannel Sjuan
    klzzwxh:11129 klzzwxh:11130 klzzwxh:11131 klzzwxh:11132 - card: user: Hometown:4:0 tune DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11133 klzzwxh:11134 klzzwxh:11135 klzzwxh:11136 - card: to different transponder
    klzzwxh:11137 klzzwxh:11138 klzzwxh:11139 klzzwxh:11140 - FreeSubChannel MD: freeing sub channel : 0
    klzzwxh:11141 klzzwxh:11142 klzzwxh:11143 klzzwxh:11144 - mdplug: FreeChannel TV3 HD (S)
    klzzwxh:11145 klzzwxh:11146 klzzwxh:11147 klzzwxh:11148 - mdplug: usage counter for channel 'TV3 HD (S)' is zero
    klzzwxh:11149 klzzwxh:11150 klzzwxh:11151 klzzwxh:11152 - tvcard:FreeSubChannel: subchannels count 1 subch#0
    klzzwxh:11153 klzzwxh:11154 klzzwxh:11155 klzzwxh:11156 - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    klzzwxh:11157 klzzwxh:11158 klzzwxh:11159 klzzwxh:11160 - TimeShifter.OnBeforeTune: resetting audio/video events
    klzzwxh:11161 klzzwxh:11162 klzzwxh:11163 klzzwxh:11164 - dvbs: Tune:DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11165 klzzwxh:11166 klzzwxh:11167 klzzwxh:11168 - dvbs: Tune:DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    klzzwxh:11169 klzzwxh:11170 klzzwxh:11171 klzzwxh:11172 - LNB low:9750 hi:10600 switch:11700
    klzzwxh:11173 klzzwxh:11174 klzzwxh:11175 klzzwxh:11176 - dvbs:channel modulation is set to ModNotSet
    klzzwxh:11177 klzzwxh:11178 klzzwxh:11179 klzzwxh:11180 - dvbs:channel FECRate is set to Rate7_8
    klzzwxh:11181 klzzwxh:11182 klzzwxh:11183 klzzwxh:11184 - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    klzzwxh:11185 klzzwxh:11186 klzzwxh:11187 klzzwxh:11188 - Turbosight: burst result = success
    klzzwxh:11189 klzzwxh:11190 klzzwxh:11191 klzzwxh:11192 - Turbosight: 22 kHz result = success
    klzzwxh:11193 klzzwxh:11194 klzzwxh:11195 klzzwxh:11196 - Turbosight: Set DVB-S2
    klzzwxh:11197 klzzwxh:11198 klzzwxh:11199 klzzwxh:11200 - dvb:Submiting tunerequest Channel:Sjuan subChannel:0
    klzzwxh:11201 klzzwxh:11202 klzzwxh:11203 klzzwxh:11204 - dvb:using existing subchannel:0
    klzzwxh:11205 klzzwxh:11206 klzzwxh:11207 klzzwxh:11208 - dvb:Submit tunerequest size:1 new:0
    klzzwxh:11209 klzzwxh:11210 klzzwxh:11211 klzzwxh:11212 - subch:0 OnBeforeTune
    klzzwxh:11213 klzzwxh:11214 klzzwxh:11215 klzzwxh:11216 - dvb:Submit tunerequest calling put_TuneRequest
    klzzwxh:11217 klzzwxh:11218 klzzwxh:11219 klzzwxh:11220 - dvb:Submit tunerequest done calling put_TuneRequest
    klzzwxh:11221 klzzwxh:11222 klzzwxh:11223 klzzwxh:11224 - subch:0 OnAfterTune
    klzzwxh:11225 klzzwxh:11226 klzzwxh:11227 klzzwxh:11228 - RunGraph
    klzzwxh:11229 klzzwxh:11230 klzzwxh:11231 klzzwxh:11232 - dvb: LockInOnSignal ok
    klzzwxh:11233 klzzwxh:11234 klzzwxh:11235 klzzwxh:11236 - subch:0 OnGraphStart
    klzzwxh:11237 klzzwxh:11238 klzzwxh:11239 klzzwxh:11240 - subch:0 Graph already running - WaitForPMT
    klzzwxh:11241 klzzwxh:11242 klzzwxh:11243 klzzwxh:11244 - subch:0 SetupPmtGrabber:pid AC sid:83C
    klzzwxh:11245 klzzwxh:11246 klzzwxh:11247 klzzwxh:11248 - subch:0 set pmt grabber pmt:AC sid:83C
    klzzwxh:11249 klzzwxh:11250 klzzwxh:11251 klzzwxh:11252 - subch:0 set ca grabber
    klzzwxh:11253 klzzwxh:11254 klzzwxh:11255 klzzwxh:11256 - TimeShifter.OnAfterTune: resetting audio/video time
    klzzwxh:11257 klzzwxh:11258 klzzwxh:11259 klzzwxh:11260 - WaitForPMT: Waiting for PMT AC
    klzzwxh:11261 klzzwxh:11262 klzzwxh:11263 klzzwxh:11264 - subch:0 OnPMTReceived() pmt:AC ran:True dynamic:False
    klzzwxh:11265 klzzwxh:11266 klzzwxh:11267 klzzwxh:11268 - WaitForPMT: Found PMT after 0,1130067 seconds.
    klzzwxh:11269 klzzwxh:11270 klzzwxh:11271 klzzwxh:11272 - subch:0 SendPmt:CA found after 0 seconds
    klzzwxh:11273 klzzwxh:11274 klzzwxh:11275 klzzwxh:11276 - subch:0 SendPmt:83C 83C FFFFFFFF 2
    klzzwxh:11277 klzzwxh:11278 klzzwxh:11279 klzzwxh:11280 - Decode pmt
    klzzwxh:11281 klzzwxh:11282 klzzwxh:11283 klzzwxh:11284 - descr1 len:6 9 4 b 0 fc 26
    klzzwxh:11285 klzzwxh:11286 klzzwxh:11287 klzzwxh:11288 - Set descriptor data with length 6
    klzzwxh:11289 klzzwxh:11290 klzzwxh:11291 klzzwxh:11292 - Set descriptor data with length 7
    klzzwxh:11293 klzzwxh:11294 klzzwxh:11295 klzzwxh:11296 - subch:0 SendPMT version:2 len:50 2108
    klzzwxh:11297 klzzwxh:11298 klzzwxh:11299 klzzwxh:11300 - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    klzzwxh:11301 klzzwxh:11302 klzzwxh:11303 klzzwxh:11304 - Turbosight: CAM not available
    klzzwxh:11305 klzzwxh:11306 klzzwxh:11307 klzzwxh:11308 - Turbosight: is CAM ready
    klzzwxh:11309 klzzwxh:11310 klzzwxh:11311 klzzwxh:11312 - Turbosight: interface not opened
    klzzwxh:11313 klzzwxh:11314 klzzwxh:11315 klzzwxh:11316 - subch:0 cam flags:False
    klzzwxh:11317 klzzwxh:11318 klzzwxh:11319 klzzwxh:11320 - subch:0 SetMpegPidMapping
    klzzwxh:11321 klzzwxh:11322 klzzwxh:11323 klzzwxh:11324 - subch:0 pid:479 pcr
    klzzwxh:11325 klzzwxh:11326 klzzwxh:11327 klzzwxh:11328 - subch:0 pid:AC pmt
    klzzwxh:11329 klzzwxh:11330 klzzwxh:11331 klzzwxh:11332 - subch:0 pid:479 video type:MPEG-2
    klzzwxh:11333 klzzwxh:11334 klzzwxh:11335 klzzwxh:11336 - subch:0 map pid:479 video type:MPEG-2
    klzzwxh:11337 klzzwxh:11338 klzzwxh:11339 klzzwxh:11340 - subch:0 pid:C44 audio lang:swe type:MPEG-2
    klzzwxh:11341 klzzwxh:11342 klzzwxh:11343 klzzwxh:11344 - subch:0 map pid:C44 audio lang:swe type:MPEG-2
    klzzwxh:11345 klzzwxh:11346 klzzwxh:11347 klzzwxh:11348 - subch:0 pid:179F teletext type:6
    klzzwxh:11349 klzzwxh:11350 klzzwxh:11351 klzzwxh:11352 - subch:0 map pid:179F teletext type:6
    klzzwxh:11353 klzzwxh:11354 klzzwxh:11355 klzzwxh:11356 - ecm len:6 9 4 B 0 FC 26
    klzzwxh:11357 klzzwxh:11358 klzzwxh:11359 klzzwxh:11360 - emm len:6 9 4 B 0 E0 30
    klzzwxh:11361 klzzwxh:11362 klzzwxh:11363 klzzwxh:11364 - Number of HWPIDS that needs to be sent to tuner :11
    klzzwxh:11365 klzzwxh:11366 klzzwxh:11367 klzzwxh:11368 - mdplug: SetChannel nr of currently decoding channels 0.
    klzzwxh:11369 klzzwxh:11370 klzzwxh:11371 klzzwxh:11372 - mdplug: SetChannel starting decryption on channel 'Sjuan' using plugin slot 1 of 1 avail.
    klzzwxh:11373 klzzwxh:11374 klzzwxh:11375 klzzwxh:11376 - emm len:6 9 4 B 0 E0 30
    klzzwxh:11377 klzzwxh:11378 klzzwxh:11379 klzzwxh:11380 - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    klzzwxh:11381 klzzwxh:11382 klzzwxh:11383 klzzwxh:11384 - ecm len:6 9 4 B 0 FC 26
    klzzwxh:11385 klzzwxh:11386 klzzwxh:11387 klzzwxh:11388 - ECM #0 CA:0xB00 ECM:0x1C26 ID:0x0
    klzzwxh:11389 klzzwxh:11390 klzzwxh:11391 klzzwxh:11392 - mdplug: tp_id:27(0x1B) sid:2108(0x83C) pmt_id:172(0xAC)
    klzzwxh:11393 klzzwxh:11394 klzzwxh:11395 klzzwxh:11396 - mdplug: #0 CA_typ:2816(0xB00) ECM:7206(0x1C26) EMM:0x30 provider:0(0x0)
    klzzwxh:11397 klzzwxh:11398 klzzwxh:11399 klzzwxh:11400 - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7206(0x1C26)
    klzzwxh:11401 klzzwxh:11402 klzzwxh:11403 klzzwxh:11404 - subch:0 stop tif
    klzzwxh:11405 klzzwxh:11406 klzzwxh:11407 klzzwxh:11408 - WaitForPmt: PMT handling took 0,1050063 seconds.
    klzzwxh:11409 klzzwxh:11410 klzzwxh:11411 klzzwxh:11412 - card: Tuner locked: True
    klzzwxh:11413 klzzwxh:11414 klzzwxh:11415 klzzwxh:11416 - klzzwxh:11423klzzwxh:11422klzzwxh:11421klzzwxh:11420klzzwxh:11419klzzwxh:11418klzzwxh:11417
    klzzwxh:10811 klzzwxh:10812 klzzwxh:10813 klzzwxh:10814 - ** SIGNAL LEVEL: 94, SIGNAL QUALITY: 82
    klzzwxh:10796 klzzwxh:10797 klzzwxh:10798 klzzwxh:10799 - klzzwxh:10806klzzwxh:10805klzzwxh:10804klzzwxh:10803klzzwxh:10802klzzwxh:10801klzzwxh:10800
    [2016-01-28 19:06:25,249] [Log ] [27 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:06:25,252] [Log ] [27 ] [INFO ] - user:Hometown add
    [2016-01-28 19:06:25,256] [Log ] [27 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:06:25,259] [Log ] [27 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:06:25,262] [Log ] [27 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:06:25,265] [Log ] [27 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:25,268] [Log ] [27 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:25,271] [Log ] [27 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:06:25,274] [Log ] [27 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:06:26,242] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:06:26,247] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:06:26,251] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:26
    [2016-01-28 19:06:26,282] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:06:26,286] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:06:26,291] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:26
    [2016-01-28 19:06:26,296] [Log ] [27 ] [INFO ] - card: WaitForFile - video and audio are seen after 1,0170593 seconds
    [2016-01-28 19:06:26,301] [Log ] [27 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:26,305] [Log ] [27 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=4, tuningdetails=DVBS:tv:Telenor Sjuan Freq:11216000 ONID:70 TSID:27 SID:2108 PMT:0xAC FTA:False LCN:10000 SymbolRate:24500 Modulation:ModNotSet Polarisation:LinearV InnerFecRate:Rate7_8 DisEqc:SimpleA band:Universal Pilot:NotSet RollOff:NotSet
    [2016-01-28 19:06:26,309] [Log ] [27 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:06:26,313] [Log ] [27 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:06:26,317] [Log ] [27 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:06:26,322] [Log ] [19 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:06:26,328] [Log ] [19 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:06:27,757] [Log ] [19 ] [INFO ] - ChannelStates.DoSetChannelStates took 1434 msec
    [2016-01-28 19:06:33,619] [Log ] [27 ] [INFO ] - Controller: TimeShiftingWouldUseCard Kanal 5 HD 3099
    [2016-01-28 19:06:33,624] [Log ] [27 ] [INFO ] - Controller: find free card for channel Kanal 5 HD
    [2016-01-28 19:06:33,628] [Log ] [27 ] [INFO ] - Controller: find card for channel Kanal 5 HD
    [2016-01-28 19:06:33,633] [Log ] [27 ] [INFO ] - Controller: got 1 tuning details for Kanal 5 HD
    [2016-01-28 19:06:33,638] [Log ] [27 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,642] [Log ] [27 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:33,645] [Log ] [27 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:33,648] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:33,652] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:33,657] [Log ] [27 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:33,660] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 32 msec
    [2016-01-28 19:06:33,664] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:33,667] [Log ] [27 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:33,670] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 46 msec
    [2016-01-28 19:06:33,725] [Log ] [27 ] [INFO ] - Controller: StartTimeShifting Kanal 5 HD 3099
    [2016-01-28 19:06:33,728] [Log ] [27 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:33,731] [Log ] [27 ] [INFO ] - Controller: find free card for channel Kanal 5 HD
    [2016-01-28 19:06:33,734] [Log ] [27 ] [INFO ] - Controller: find card for channel Kanal 5 HD
    [2016-01-28 19:06:33,738] [Log ] [27 ] [INFO ] - Controller: got 1 tuning details for Kanal 5 HD
    [2016-01-28 19:06:33,741] [Log ] [27 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,743] [Log ] [27 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:33,746] [Log ] [27 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:33,750] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:33,753] [Log ] [27 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:33,755] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 21 msec
    [2016-01-28 19:06:33,758] [Log ] [27 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:33,761] [Log ] [27 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 29 msec
    [2016-01-28 19:06:33,766] [Log ] [27 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=5, tuningdetails=DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,769] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:33,772] [Log ] [27 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:33,775] [Log ] [27 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:06:33,778] [Log ] [27 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:06:33,781] [Log ] [27 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3099, ticket=5, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:06:33,784] [Log ] [27 ] [INFO ] - card: CardTune 4 Kanal 5 HD (S) Hometown:4:-1
    [2016-01-28 19:06:33,787] [Log ] [27 ] [INFO ] - card: Tune on card 4 to subchannel Kanal 5 HD (S)
    [2016-01-28 19:06:33,790] [Log ] [27 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,798] [Log ] [27 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:06:33,801] [Log ] [27 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:06:33,804] [Log ] [27 ] [INFO ] - mdplug: FreeChannel Sjuan
    [2016-01-28 19:06:33,807] [Log ] [27 ] [INFO ] - mdplug: usage counter for channel 'Sjuan' is zero
    [2016-01-28 19:06:33,810] [Log ] [27 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:06:33,813] [Log ] [27 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:06:33,815] [Log ] [27 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:06:33,818] [Log ] [27 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,821] [Log ] [27 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:33,824] [Log ] [27 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:06:33,826] [Log ] [27 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:06:33,829] [Log ] [27 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:06:33,832] [Log ] [27 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:06:33,837] [Log ] [27 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:06:33,841] [Log ] [27 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:06:33,843] [Log ] [27 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:06:33,947] [Log ] [27 ] [INFO ] - dvb:Submiting tunerequest Channel:Kanal 5 HD (S) subChannel:0
    [2016-01-28 19:06:33,951] [Log ] [27 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:06:33,954] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:06:33,958] [Log ] [27 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:06:33,962] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:06:34,154] [Log ] [27 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:06:34,159] [Log ] [27 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:06:34,163] [Log ] [27 ] [INFO ] - RunGraph
    [2016-01-28 19:06:34,167] [Log ] [27 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:06:34,171] [Log ] [27 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:06:34,175] [Log ] [27 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:06:34,180] [Log ] [27 ] [INFO ] - subch:0 SetupPmtGrabber:pid 132 sid:1A91
    [2016-01-28 19:06:34,184] [Log ] [27 ] [INFO ] - subch:0 set pmt grabber pmt:132 sid:1A91
    [2016-01-28 19:06:34,188] [Log ] [27 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:06:34,192] [Log ] [27 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:06:34,196] [Log ] [27 ] [DEBUG] - WaitForPMT: Waiting for PMT 132
    [2016-01-28 19:06:34,217] [Log ] [29 ] [INFO ] - subch:OnCaReceived()
    [2016-01-28 19:06:34,312] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:132 ran:True dynamic:False
    [2016-01-28 19:06:34,316] [Log ] [27 ] [DEBUG] - WaitForPMT: Found PMT after 0,1200067 seconds.
    [2016-01-28 19:06:34,320] [Log ] [27 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:06:34,324] [Log ] [27 ] [INFO ] - subch:0 SendPmt:1A91 1A91 FFFFFFFF 12
    [2016-01-28 19:06:34,328] [Log ] [27 ] [INFO ] - Decode pmt
    [2016-01-28 19:06:34,332] [Log ] [27 ] [INFO ] - descr1 len:6 9 4 b 0 fb c0
    [2016-01-28 19:06:34,336] [Log ] [27 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:06:34,340] [Log ] [27 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:06:34,344] [Log ] [27 ] [INFO ] - subch:0 SendPMT version:18 len:50 6801
    [2016-01-28 19:06:34,348] [Log ] [27 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:06:34,352] [Log ] [27 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:06:34,356] [Log ] [27 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:34,360] [Log ] [27 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:34,363] [Log ] [27 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:06:34,366] [Log ] [27 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:06:34,368] [Log ] [27 ] [INFO ] - subch:0 pid:4E7 pcr
    [2016-01-28 19:06:34,371] [Log ] [27 ] [INFO ] - subch:0 pid:132 pmt
    [2016-01-28 19:06:34,374] [Log ] [27 ] [INFO ] - subch:0 pid:4E7 video type:H.264
    [2016-01-28 19:06:34,376] [Log ] [27 ] [INFO ] - subch:0 map pid:4E7 video type:H.264
    [2016-01-28 19:06:34,379] [Log ] [27 ] [INFO ] - subch:0 pid:CB7 audio lang:swe type:MPEG-2
    [2016-01-28 19:06:34,382] [Log ] [27 ] [INFO ] - subch:0 map pid:CB7 audio lang:swe type:MPEG-2
    [2016-01-28 19:06:34,384] [Log ] [27 ] [INFO ] - subch:0 pid:18A6 teletext type:6
    [2016-01-28 19:06:34,387] [Log ] [27 ] [INFO ] - subch:0 map pid:18A6 teletext type:6
    [2016-01-28 19:06:34,390] [Log ] [27 ] [INFO ] - ecm len:6 9 4 B 0 FB C0
    [2016-01-28 19:06:34,393] [Log ] [27 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:34,395] [Log ] [27 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :11
    [2016-01-28 19:06:34,399] [Log ] [27 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:06:34,401] [Log ] [27 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'Kanal 5 HD (S)' using plugin slot 1 of 1 avail.
    [2016-01-28 19:06:34,404] [Log ] [27 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:34,407] [Log ] [27 ] [INFO ] - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    [2016-01-28 19:06:34,409] [Log ] [27 ] [INFO ] - ecm len:6 9 4 B 0 FB C0
    [2016-01-28 19:06:34,412] [Log ] [27 ] [INFO ] - ECM #0 CA:0xB00 ECM:0x1BC0 ID:0x0
    [2016-01-28 19:06:34,415] [Log ] [27 ] [INFO ] - mdplug: tp_id:67(0x43) sid:6801(0x1A91) pmt_id:306(0x132)
    [2016-01-28 19:06:34,418] [Log ] [27 ] [INFO ] - mdplug: #0 CA_typ:2816(0xB00) ECM:7104(0x1BC0) EMM:0x30 provider:0(0x0)
    [2016-01-28 19:06:34,421] [Log ] [27 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7104(0x1BC0)
    [2016-01-28 19:06:34,424] [Log ] [27 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:06:34,427] [Log ] [27 ] [DEBUG] - WaitForPmt: PMT handling took 0,1070058 seconds.
    [2016-01-28 19:06:34,435] [Log ] [27 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:06:34,438] [Log ] [27 ] [INFO ] - klzzwxh:10791klzzwxh:10790klzzwxh:10789klzzwxh:10788klzzwxh:10787klzzwxh:10786klzzwxh:10785
    klzzwxh:10058 klzzwxh:10059 klzzwxh:10060 klzzwxh:10061 - ** SIGNAL LEVEL: 95, SIGNAL QUALITY: 82
    klzzwxh:10073 klzzwxh:10074 klzzwxh:10075 klzzwxh:10076 - klzzwxh:10784klzzwxh:10783klzzwxh:10782klzzwxh:10781klzzwxh:10780klzzwxh:10779klzzwxh:10778
    klzzwxh:10081 klzzwxh:10082 klzzwxh:10083 klzzwxh:10084 - card: tuned user: Hometown subchannel: 0
    klzzwxh:10085 klzzwxh:10086 klzzwxh:10087 klzzwxh:10088 - user:Hometown add
    klzzwxh:10089 klzzwxh:10090 klzzwxh:10091 klzzwxh:10092 - card2:Hometown 4 0
    klzzwxh:10093 klzzwxh:10094 klzzwxh:10095 klzzwxh:10096 - Timeshifting started - Recordings=0 TimeShiftingActive=True
    klzzwxh:10097 klzzwxh:10098 klzzwxh:10099 klzzwxh:10100 - TVServerKodi: OnTvServerEvent: StartTimeShifting
    klzzwxh:10101 klzzwxh:10102 klzzwxh:10103 klzzwxh:10104 - Controller: epg stop
    klzzwxh:10105 klzzwxh:10106 klzzwxh:10107 klzzwxh:10108 - card: StartTimeShifting 4 C:klzzwxh:10109rogramDataklzzwxh:10110eam MediaPortalklzzwxh:10111ediaPortal TV Serverklzzwxh:10112imeshiftbufferklzzwxh:10113ive4-0.ts
    klzzwxh:10114 klzzwxh:10115 klzzwxh:10116 klzzwxh:10117 - card: CAM enabled : True
    klzzwxh:10118 klzzwxh:10119 klzzwxh:10120 klzzwxh:10121 - card: WaitForFile - waiting _eventAudio & _eventVideo
    klzzwxh:10122 klzzwxh:10123 klzzwxh:10124 klzzwxh:10125 - PID seen - type = Video
    klzzwxh:10126 klzzwxh:10127 klzzwxh:10128 klzzwxh:10129 - audioVideoEventHandler Video
    klzzwxh:10130 klzzwxh:10131 klzzwxh:10132 klzzwxh:10133 - video last seen at 2016-01-28 19:06:34
    klzzwxh:10134 klzzwxh:10135 klzzwxh:10136 klzzwxh:10137 - video last seen at 2016-01-28 19:06:35
    klzzwxh:10138 klzzwxh:10139 klzzwxh:10140 klzzwxh:10141 - PID seen - type = Audio
    klzzwxh:10142 klzzwxh:10143 klzzwxh:10144 klzzwxh:10145 - audioVideoEventHandler Audio
    klzzwxh:10146 klzzwxh:10147 klzzwxh:10148 klzzwxh:10149 - audio last seen at 2016-01-28 19:06:35
    klzzwxh:10150 klzzwxh:10151 klzzwxh:10152 klzzwxh:10153 - card: WaitForFile - video and audio are seen after 0,5900344 seconds
    klzzwxh:10154 klzzwxh:10155 klzzwxh:10156 klzzwxh:10157 - audio last seen at 2016-01-28 19:06:35
    klzzwxh:10158 klzzwxh:10159 klzzwxh:10160 klzzwxh:10161 - Controller: StartTimeShifting started on card:4 to C:klzzwxh:10162rogramDataklzzwxh:10163eam MediaPortalklzzwxh:10164ediaPortal TV Serverklzzwxh:10165imeshiftbufferklzzwxh:10166ive4-0.ts
    klzzwxh:10167 klzzwxh:10168 klzzwxh:10169 klzzwxh:10170 - CardReservation.RemoveTuneTicket: removed reservation with id=5, tuningdetails=DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    klzzwxh:10171 klzzwxh:10172 klzzwxh:10173 klzzwxh:10174 - Controller: Hometown 4 0
    klzzwxh:10175 klzzwxh:10176 klzzwxh:10177 klzzwxh:10178 - TVServerKodi: OnTvServerEvent: EndZapChannel
    klzzwxh:10179 klzzwxh:10180 klzzwxh:10181 klzzwxh:10182 - control2:Hometown 4 0
    klzzwxh:10183 klzzwxh:10184 klzzwxh:10185 klzzwxh:10186 - Controller: DoSetChannelStates for 1033 channels
    klzzwxh:10187 klzzwxh:10188 klzzwxh:10189 klzzwxh:10190 - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    klzzwxh:10191 klzzwxh:10192 klzzwxh:10193 klzzwxh:10194 - ChannelStates.DoSetChannelStates took 1515 msec
    klzzwxh:10195 klzzwxh:10196 klzzwxh:10197 klzzwxh:10198 - Controller: TimeShiftingWouldUseCard TV6 3086
    klzzwxh:10199 klzzwxh:10200 klzzwxh:10201 klzzwxh:10202 - Controller: find free card for channel TV6
    klzzwxh:10203 klzzwxh:10204 klzzwxh:10205 klzzwxh:10206 - Controller: find card for channel TV6
    klzzwxh:10207 klzzwxh:10208 klzzwxh:10209 klzzwxh:10210 - Controller: got 1 tuning details for TV6
    klzzwxh:10211 klzzwxh:10212 klzzwxh:10213 klzzwxh:10214 - Controller: channel #1 DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10215 klzzwxh:10216 klzzwxh:10217 klzzwxh:10218 - Controller: card:1 type:RadioWebStream is disabled
    klzzwxh:10219 klzzwxh:10220 klzzwxh:10221 klzzwxh:10222 - Controller: card:5 type:DvbS is disabled
    klzzwxh:10223 klzzwxh:10224 klzzwxh:10225 klzzwxh:10226 - Controller: card:4 type:DvbS can tune to channel
    klzzwxh:10227 klzzwxh:10228 klzzwxh:10229 klzzwxh:10230 - Controller: card:4 type:DvbS users: 0
    klzzwxh:10231 klzzwxh:10232 klzzwxh:10233 klzzwxh:10234 - Controller: found 1 card(s) for channel
    klzzwxh:10235 klzzwxh:10236 klzzwxh:10237 klzzwxh:10238 - AdvancedCardAllocation.GetAvailableCardsForChannel took 53 msec
    klzzwxh:10239 klzzwxh:10240 klzzwxh:10241 klzzwxh:10242 - Controller: card:4 type:DvbS is available
    klzzwxh:10243 klzzwxh:10244 klzzwxh:10245 klzzwxh:10246 - Controller: found 1 free card(s)
    klzzwxh:10247 klzzwxh:10248 klzzwxh:10249 klzzwxh:10250 - AdvancedCardAllocation.GetFreeCardsForChannel took 70 msec
    klzzwxh:10251 klzzwxh:10252 klzzwxh:10253 klzzwxh:10254 - Controller: StartTimeShifting TV6 3086
    klzzwxh:10255 klzzwxh:10256 klzzwxh:10257 klzzwxh:10258 - Controller: epg stop
    klzzwxh:10259 klzzwxh:10260 klzzwxh:10261 klzzwxh:10262 - Controller: find free card for channel TV6
    klzzwxh:10263 klzzwxh:10264 klzzwxh:10265 klzzwxh:10266 - Controller: find card for channel TV6
    klzzwxh:10267 klzzwxh:10268 klzzwxh:10269 klzzwxh:10270 - Controller: got 1 tuning details for TV6
    klzzwxh:10271 klzzwxh:10272 klzzwxh:10273 klzzwxh:10274 - Controller: channel #1 DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10275 klzzwxh:10276 klzzwxh:10277 klzzwxh:10278 - Controller: card:1 type:RadioWebStream is disabled
    klzzwxh:10279 klzzwxh:10280 klzzwxh:10281 klzzwxh:10282 - Controller: card:5 type:DvbS is disabled
    klzzwxh:10283 klzzwxh:10284 klzzwxh:10285 klzzwxh:10286 - Controller: card:4 type:DvbS can tune to channel
    klzzwxh:10287 klzzwxh:10288 klzzwxh:10289 klzzwxh:10290 - Controller: found 1 card(s) for channel
    klzzwxh:10291 klzzwxh:10292 klzzwxh:10293 klzzwxh:10294 - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    klzzwxh:10295 klzzwxh:10296 klzzwxh:10297 klzzwxh:10298 - Controller: found 1 free card(s)
    klzzwxh:10299 klzzwxh:10300 klzzwxh:10301 klzzwxh:10302 - AdvancedCardAllocation.GetFreeCardsForChannel took 30 msec
    klzzwxh:10303 klzzwxh:10304 klzzwxh:10305 klzzwxh:10306 - CardReservationBase.RequestCardTuneReservation: placed reservation with id=6, tuningdetails=DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10307 klzzwxh:10308 klzzwxh:10309 klzzwxh:10310 - Controller: card:4 type:DvbS users: 0
    klzzwxh:10311 klzzwxh:10312 klzzwxh:10313 klzzwxh:10314 - Controller: card:4 type:DvbS is available
    klzzwxh:10315 klzzwxh:10316 klzzwxh:10317 klzzwxh:10318 - Controller: try max 1 of 1 cards for timeshifting
    klzzwxh:10319 klzzwxh:10320 klzzwxh:10321 klzzwxh:10322 - TVServerKodi: OnTvServerEvent: StartZapChannel
    klzzwxh:10323 klzzwxh:10324 klzzwxh:10325 klzzwxh:10326 - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3086, ticket=6, tunestate=Tuning, stopstate=Idle
    klzzwxh:10327 klzzwxh:10328 klzzwxh:10329 klzzwxh:10330 - card: CardTune 4 TV6 Hometown:4:-1
    klzzwxh:10331 klzzwxh:10332 klzzwxh:10333 klzzwxh:10334 - card: Tune on card 4 to subchannel TV6
    klzzwxh:10335 klzzwxh:10336 klzzwxh:10337 klzzwxh:10338 - card: user: Hometown:4:0 tune DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10339 klzzwxh:10340 klzzwxh:10341 klzzwxh:10342 - card: to different transponder
    klzzwxh:10343 klzzwxh:10344 klzzwxh:10345 klzzwxh:10346 - FreeSubChannel MD: freeing sub channel : 0
    klzzwxh:10347 klzzwxh:10348 klzzwxh:10349 klzzwxh:10350 - mdplug: FreeChannel Kanal 5 HD (S)
    klzzwxh:10351 klzzwxh:10352 klzzwxh:10353 klzzwxh:10354 - mdplug: usage counter for channel 'Kanal 5 HD (S)' is zero
    klzzwxh:10355 klzzwxh:10356 klzzwxh:10357 klzzwxh:10358 - tvcard:FreeSubChannel: subchannels count 1 subch#0
    klzzwxh:10359 klzzwxh:10360 klzzwxh:10361 klzzwxh:10362 - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    klzzwxh:10363 klzzwxh:10364 klzzwxh:10365 klzzwxh:10366 - TimeShifter.OnBeforeTune: resetting audio/video events
    klzzwxh:10367 klzzwxh:10368 klzzwxh:10369 klzzwxh:10370 - dvbs: Tune:DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10371 klzzwxh:10372 klzzwxh:10373 klzzwxh:10374 - dvbs: Tune:DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    klzzwxh:10375 klzzwxh:10376 klzzwxh:10377 klzzwxh:10378 - LNB low:9750 hi:10600 switch:11700
    klzzwxh:10379 klzzwxh:10380 klzzwxh:10381 klzzwxh:10382 - dvbs:channel modulation is set to ModQpsk
    klzzwxh:10383 klzzwxh:10384 klzzwxh:10385 klzzwxh:10386 - dvbs:channel FECRate is set to Rate3_4
    klzzwxh:10387 klzzwxh:10388 klzzwxh:10389 klzzwxh:10390 - Turbosight: set tone state, burst = DataBurst, 22 kHz = On
    klzzwxh:10391 klzzwxh:10392 klzzwxh:10393 klzzwxh:10394 - Turbosight: burst result = success
    klzzwxh:10395 klzzwxh:10396 klzzwxh:10397 klzzwxh:10398 - Turbosight: 22 kHz result = success
    klzzwxh:10399 klzzwxh:10400 klzzwxh:10401 klzzwxh:10402 - Turbosight: Set DVB-S2
    klzzwxh:10403 klzzwxh:10404 klzzwxh:10405 klzzwxh:10406 - dvb:Submiting tunerequest Channel:TV6 subChannel:0
    klzzwxh:10407 klzzwxh:10408 klzzwxh:10409 klzzwxh:10410 - dvb:using existing subchannel:0
    klzzwxh:10411 klzzwxh:10412 klzzwxh:10413 klzzwxh:10414 - dvb:Submit tunerequest size:1 new:0
    klzzwxh:10415 klzzwxh:10416 klzzwxh:10417 klzzwxh:10418 - subch:0 OnBeforeTune
    klzzwxh:10419 klzzwxh:10420 klzzwxh:10421 klzzwxh:10422 - dvb:Submit tunerequest calling put_TuneRequest
    klzzwxh:10423 klzzwxh:10424 klzzwxh:10425 klzzwxh:10426 - dvb:Submit tunerequest done calling put_TuneRequest
    klzzwxh:10427 klzzwxh:10428 klzzwxh:10429 klzzwxh:10430 - subch:0 OnAfterTune
    klzzwxh:10431 klzzwxh:10432 klzzwxh:10433 klzzwxh:10434 - RunGraph
    klzzwxh:10435 klzzwxh:10436 klzzwxh:10437 klzzwxh:10438 - dvb: LockInOnSignal ok
    klzzwxh:10439 klzzwxh:10440 klzzwxh:10441 klzzwxh:10442 - subch:0 OnGraphStart
    klzzwxh:10443 klzzwxh:10444 klzzwxh:10445 klzzwxh:10446 - subch:0 Graph already running - WaitForPMT
    klzzwxh:10447 klzzwxh:10448 klzzwxh:10449 klzzwxh:10450 - subch:0 SetupPmtGrabber:pid 488 sid:488
    klzzwxh:10451 klzzwxh:10452 klzzwxh:10453 klzzwxh:10454 - subch:0 set pmt grabber pmt:488 sid:488
    klzzwxh:10455 klzzwxh:10456 klzzwxh:10457 klzzwxh:10458 - subch:0 set ca grabber
    klzzwxh:10459 klzzwxh:10460 klzzwxh:10461 klzzwxh:10462 - TimeShifter.OnAfterTune: resetting audio/video time
    klzzwxh:10463 klzzwxh:10464 klzzwxh:10465 klzzwxh:10466 - WaitForPMT: Waiting for PMT 488
    klzzwxh:10467 klzzwxh:10468 klzzwxh:10469 klzzwxh:10470 - subch:OnCaReceived()
    klzzwxh:10471 klzzwxh:10472 klzzwxh:10473 klzzwxh:10474 - subch:0 OnPMTReceived() pmt:488 ran:True dynamic:False
    klzzwxh:10475 klzzwxh:10476 klzzwxh:10477 klzzwxh:10478 - WaitForPMT: Found PMT after 0,0320016 seconds.
    klzzwxh:10479 klzzwxh:10480 klzzwxh:10481 klzzwxh:10482 - subch:0 SendPmt:CA found after 0 seconds
    klzzwxh:10483 klzzwxh:10484 klzzwxh:10485 klzzwxh:10486 - subch:0 SendPmt:488 488 FFFFFFFF 11
    klzzwxh:10487 klzzwxh:10488 klzzwxh:10489 klzzwxh:10490 - Decode pmt
    klzzwxh:10491 klzzwxh:10492 klzzwxh:10493 klzzwxh:10494 - descr2 pid:489 len:6 9 4 9 f e4 8d
    klzzwxh:10495 klzzwxh:10496 klzzwxh:10497 klzzwxh:10498 - descr2 pid:489 len:6 9 4 9 3e e0 98
    klzzwxh:10499 klzzwxh:10500 klzzwxh:10501 klzzwxh:10502 - descr2 pid:489 len:6 9 4 9 40 e1 92
    klzzwxh:10503 klzzwxh:10504 klzzwxh:10505 klzzwxh:10506 - Set descriptor data with length 7
    klzzwxh:10507 klzzwxh:10508 klzzwxh:10509 klzzwxh:10510 - Set descriptor data with length 6
    klzzwxh:10511 klzzwxh:10512 klzzwxh:10513 klzzwxh:10514 - descr2 pid:48A len:6 9 4 9 f e4 8d
    klzzwxh:10515 klzzwxh:10516 klzzwxh:10517 klzzwxh:10518 - descr2 pid:48A len:6 9 4 9 3e e0 98
    klzzwxh:10519 klzzwxh:10520 klzzwxh:10521 klzzwxh:10522 - descr2 pid:48A len:6 9 4 9 40 e1 92
    klzzwxh:10523 klzzwxh:10524 klzzwxh:10525 klzzwxh:10526 - Set descriptor data with length 6
    klzzwxh:10527 klzzwxh:10528 klzzwxh:10529 klzzwxh:10530 - descr2 pid:48B len:6 9 4 9 f e4 8d
    klzzwxh:10531 klzzwxh:10532 klzzwxh:10533 klzzwxh:10534 - descr2 pid:48B len:6 9 4 9 3e e0 98
    klzzwxh:10535 klzzwxh:10536 klzzwxh:10537 klzzwxh:10538 - descr2 pid:48B len:6 9 4 9 40 e1 92
    klzzwxh:10539 klzzwxh:10540 klzzwxh:10541 klzzwxh:10542 - subch:0 SendPMT version:17 len:109 1160
    klzzwxh:10543 klzzwxh:10544 klzzwxh:10545 klzzwxh:10546 - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    klzzwxh:10547 klzzwxh:10548 klzzwxh:10549 klzzwxh:10550 - Turbosight: CAM not available
    klzzwxh:10551 klzzwxh:10552 klzzwxh:10553 klzzwxh:10554 - Turbosight: is CAM ready
    klzzwxh:10555 klzzwxh:10556 klzzwxh:10557 klzzwxh:10558 - Turbosight: interface not opened
    klzzwxh:10559 klzzwxh:10560 klzzwxh:10561 klzzwxh:10562 - subch:0 cam flags:False
    klzzwxh:10563 klzzwxh:10564 klzzwxh:10565 klzzwxh:10566 - subch:0 SetMpegPidMapping
    klzzwxh:10567 klzzwxh:10568 klzzwxh:10569 klzzwxh:10570 - subch:0 pid:489 pcr
    klzzwxh:10571 klzzwxh:10572 klzzwxh:10573 klzzwxh:10574 - subch:0 pid:488 pmt
    klzzwxh:10575 klzzwxh:10576 klzzwxh:10577 klzzwxh:10578 - subch:0 pid:489 video type:MPEG-2
    klzzwxh:10579 klzzwxh:10580 klzzwxh:10581 klzzwxh:10582 - subch:0 map pid:489 video type:MPEG-2
    klzzwxh:10583 klzzwxh:10584 klzzwxh:10585 klzzwxh:10586 - subch:0 pid:48E teletext type:6
    klzzwxh:10587 klzzwxh:10588 klzzwxh:10589 klzzwxh:10590 - subch:0 map pid:48E teletext type:6
    klzzwxh:10591 klzzwxh:10592 klzzwxh:10593 klzzwxh:10594 - subch:0 pid:48A audio lang:swe type:MPEG-1
    klzzwxh:10595 klzzwxh:10596 klzzwxh:10597 klzzwxh:10598 - subch:0 map pid:48A audio lang:swe type:MPEG-1
    klzzwxh:10599 klzzwxh:10600 klzzwxh:10601 klzzwxh:10602 - subch:0 pid:48B audio lang:syn type:MPEG-1
    klzzwxh:10603 klzzwxh:10604 klzzwxh:10605 klzzwxh:10606 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10607 klzzwxh:10608 klzzwxh:10609 klzzwxh:10610 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10611 klzzwxh:10612 klzzwxh:10613 klzzwxh:10614 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10615 klzzwxh:10616 klzzwxh:10617 klzzwxh:10618 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10619 klzzwxh:10620 klzzwxh:10621 klzzwxh:10622 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10623 klzzwxh:10624 klzzwxh:10625 klzzwxh:10626 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10627 klzzwxh:10628 klzzwxh:10629 klzzwxh:10630 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10631 klzzwxh:10632 klzzwxh:10633 klzzwxh:10634 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10635 klzzwxh:10636 klzzwxh:10637 klzzwxh:10638 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10639 klzzwxh:10640 klzzwxh:10641 klzzwxh:10642 - emm len:6 9 4 9 F E0 C0
    klzzwxh:10643 klzzwxh:10644 klzzwxh:10645 klzzwxh:10646 - emm len:6 9 4 9 3E E0 C1
    klzzwxh:10647 klzzwxh:10648 klzzwxh:10649 klzzwxh:10650 - emm len:6 9 4 9 40 E0 C2
    klzzwxh:10651 klzzwxh:10652 klzzwxh:10653 klzzwxh:10654 - Number of HWPIDS that needs to be sent to tuner :16
    klzzwxh:10655 klzzwxh:10656 klzzwxh:10657 klzzwxh:10658 - mdplug: SetChannel nr of currently decoding channels 0.
    klzzwxh:10659 klzzwxh:10660 klzzwxh:10661 klzzwxh:10662 - mdplug: SetChannel starting decryption on channel 'TV6' using plugin slot 1 of 1 avail.
    klzzwxh:10663 klzzwxh:10664 klzzwxh:10665 klzzwxh:10666 - emm len:6 9 4 9 F E0 C0
    klzzwxh:10667 klzzwxh:10668 klzzwxh:10669 klzzwxh:10670 - emm len:6 9 4 9 3E E0 C1
    klzzwxh:10671 klzzwxh:10672 klzzwxh:10673 klzzwxh:10674 - emm len:6 9 4 9 40 E0 C2
    klzzwxh:10675 klzzwxh:10676 klzzwxh:10677 klzzwxh:10678 - EMM #0 CA:0x90F EMM:0xC0 ID:0x0
    klzzwxh:10679 klzzwxh:10680 klzzwxh:10681 klzzwxh:10682 - EMM #1 CA:0x93E EMM:0xC1 ID:0x0
    klzzwxh:10683 klzzwxh:10684 klzzwxh:10685 klzzwxh:10686 - EMM #2 CA:0x940 EMM:0xC2 ID:0x0
    klzzwxh:10687 klzzwxh:10688 klzzwxh:10689 klzzwxh:10690 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10691 klzzwxh:10692 klzzwxh:10693 klzzwxh:10694 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10695 klzzwxh:10696 klzzwxh:10697 klzzwxh:10698 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10699 klzzwxh:10700 klzzwxh:10701 klzzwxh:10702 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10703 klzzwxh:10704 klzzwxh:10705 klzzwxh:10706 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10707 klzzwxh:10708 klzzwxh:10709 klzzwxh:10710 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10711 klzzwxh:10712 klzzwxh:10713 klzzwxh:10714 - ecm len:6 9 4 9 F E4 8D
    klzzwxh:10715 klzzwxh:10716 klzzwxh:10717 klzzwxh:10718 - ecm len:6 9 4 9 3E E0 98
    klzzwxh:10719 klzzwxh:10720 klzzwxh:10721 klzzwxh:10722 - ecm len:6 9 4 9 40 E1 92
    klzzwxh:10723 klzzwxh:10724 klzzwxh:10725 klzzwxh:10726 - ECM #0 CA:0x90F ECM:0x48D ID:0x0
    klzzwxh:10727 klzzwxh:10728 klzzwxh:10729 klzzwxh:10730 - ECM #1 CA:0x93E ECM:0x98 ID:0x0
    klzzwxh:10731 klzzwxh:10732 klzzwxh:10733 klzzwxh:10734 - ECM #2 CA:0x940 ECM:0x192 ID:0x0
    klzzwxh:10735 klzzwxh:10736 klzzwxh:10737 klzzwxh:10738 - mdplug: tp_id:3(0x3) sid:1160(0x488) pmt_id:1160(0x488)
    klzzwxh:10739 klzzwxh:10740 klzzwxh:10741 klzzwxh:10742 - mdplug: #0 CA_typ:2319(0x90F) ECM:1165(0x48D) EMM:0xC0 provider:0(0x0)
    klzzwxh:10743 klzzwxh:10744 klzzwxh:10745 klzzwxh:10746 - mdplug: #1 CA_typ:2366(0x93E) ECM:152(0x98) EMM:0xC1 provider:0(0x0)
    klzzwxh:10747 klzzwxh:10748 klzzwxh:10749 klzzwxh:10750 - mdplug: #2 CA_typ:2368(0x940) ECM:402(0x192) EMM:0xC2 provider:0(0x0)
    klzzwxh:10751 klzzwxh:10752 klzzwxh:10753 klzzwxh:10754 - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:3 ECM_PID:1165(0x48D)
    klzzwxh:10755 klzzwxh:10756 klzzwxh:10757 klzzwxh:10758 - subch:0 stop tif
    klzzwxh:10759 klzzwxh:10760 klzzwxh:10761 klzzwxh:10762 - WaitForPmt: PMT handling took 0,1920112 seconds.
    klzzwxh:10763 klzzwxh:10764 klzzwxh:10765 klzzwxh:10766 - card: Tuner locked: True
    klzzwxh:10767 klzzwxh:10768 klzzwxh:10769 klzzwxh:10770 - klzzwxh:10777klzzwxh:10776klzzwxh:10775klzzwxh:10774klzzwxh:10773klzzwxh:10772klzzwxh:10771
    klzzwxh:10077 klzzwxh:10078 klzzwxh:10079 klzzwxh:10080 - ** SIGNAL LEVEL: 94, SIGNAL QUALITY: 80
    klzzwxh:10062 klzzwxh:10063 klzzwxh:10064 klzzwxh:10065 - klzzwxh:10072klzzwxh:10071klzzwxh:10070klzzwxh:10069klzzwxh:10068klzzwxh:10067klzzwxh:10066
    [2016-01-28 19:06:41,447] [Log ] [33 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:06:41,450] [Log ] [33 ] [INFO ] - user:Hometown add
    [2016-01-28 19:06:41,454] [Log ] [33 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:06:41,457] [Log ] [33 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:06:41,461] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:06:41,464] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:41,467] [Log ] [33 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:41,470] [Log ] [33 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:06:41,473] [Log ] [33 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:06:41,957] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:06:41,962] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:06:41,966] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,970] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,974] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,978] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:06:41,981] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:06:41,984] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,987] [Log ] [33 ] [INFO ] - card: WaitForFile - video and audio are seen after 0,51103 seconds
    [2016-01-28 19:06:41,989] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,992] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:41,995] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:41,998] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=6, tuningdetails=DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:06:42,001] [Log ] [33 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:06:42,004] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:06:42,008] [Log ] [33 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:06:42,012] [Log ] [38 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:06:42,018] [Log ] [38 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:06:42,033] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:06:42,038] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:41
    [2016-01-28 19:06:42,043] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:42
    [2016-01-28 19:06:42,046] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:42
    [2016-01-28 19:06:42,049] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:42
    [2016-01-28 19:06:43,422] [Log ] [38 ] [INFO ] - ChannelStates.DoSetChannelStates took 1409 msec
    [2016-01-28 19:06:47,695] [Log ] [33 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV4 HD 3476
    [2016-01-28 19:06:47,700] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:06:47,704] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:06:47,710] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:06:47,713] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,716] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:47,719] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:47,723] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:47,727] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:47,732] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:47,735] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 30 msec
    [2016-01-28 19:06:47,738] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:47,741] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:47,744] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 44 msec
    [2016-01-28 19:06:47,779] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting TV4 HD 3476
    [2016-01-28 19:06:47,782] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:47,785] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:06:47,788] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:06:47,791] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:06:47,795] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,797] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:47,801] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:47,804] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:47,807] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:47,810] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    [2016-01-28 19:06:47,813] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:47,815] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 30 msec
    [2016-01-28 19:06:47,821] [Log ] [33 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=7, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,824] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:47,827] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:47,830] [Log ] [33 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:06:47,833] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:06:47,835] [Log ] [33 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3476, ticket=7, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:06:47,838] [Log ] [33 ] [INFO ] - card: CardTune 4 TV4 HD Hometown:4:-1
    [2016-01-28 19:06:47,842] [Log ] [33 ] [INFO ] - card: Tune on card 4 to subchannel TV4 HD
    [2016-01-28 19:06:47,845] [Log ] [33 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,852] [Log ] [33 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:06:47,856] [Log ] [33 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:06:47,858] [Log ] [33 ] [INFO ] - mdplug: FreeChannel TV6
    [2016-01-28 19:06:47,861] [Log ] [33 ] [INFO ] - mdplug: usage counter for channel 'TV6' is zero
    [2016-01-28 19:06:47,864] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:06:47,867] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:06:47,869] [Log ] [33 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:06:47,872] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,875] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:47,878] [Log ] [33 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:06:47,881] [Log ] [33 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:06:47,884] [Log ] [33 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:06:47,886] [Log ] [33 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:06:47,891] [Log ] [33 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:06:47,895] [Log ] [33 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:06:47,898] [Log ] [33 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:06:48,002] [Log ] [33 ] [INFO ] - dvb:Submiting tunerequest Channel:TV4 HD subChannel:0
    [2016-01-28 19:06:48,006] [Log ] [33 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:06:48,010] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:06:48,014] [Log ] [33 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:06:48,018] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:06:48,210] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:06:48,215] [Log ] [33 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:06:48,219] [Log ] [33 ] [INFO ] - RunGraph
    [2016-01-28 19:06:48,223] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:06:48,225] [Log ] [33 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:06:48,228] [Log ] [33 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:06:48,231] [Log ] [33 ] [INFO ] - subch:0 SetupPmtGrabber:pid 4F sid:57D
    [2016-01-28 19:06:48,234] [Log ] [33 ] [INFO ] - subch:0 set pmt grabber pmt:4F sid:57D
    [2016-01-28 19:06:48,236] [Log ] [33 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:06:48,239] [Log ] [33 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:06:48,243] [Log ] [33 ] [DEBUG] - WaitForPMT: Waiting for PMT 4F
    [2016-01-28 19:06:48,339] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:4F ran:True dynamic:False
    [2016-01-28 19:06:48,343] [Log ] [33 ] [DEBUG] - WaitForPMT: Found PMT after 0,1000064 seconds.
    [2016-01-28 19:06:48,347] [Log ] [33 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:06:48,351] [Log ] [33 ] [INFO ] - subch:0 SendPmt:57D 57D FFFFFFFF 14
    [2016-01-28 19:06:48,355] [Log ] [33 ] [INFO ] - Decode pmt
    [2016-01-28 19:06:48,359] [Log ] [33 ] [INFO ] - descr1 len:6 9 4 b 0 fb d0
    [2016-01-28 19:06:48,363] [Log ] [33 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:06:48,367] [Log ] [33 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:06:48,371] [Log ] [33 ] [INFO ] - subch:0 SendPMT version:20 len:53 1405
    [2016-01-28 19:06:48,375] [Log ] [33 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:06:48,379] [Log ] [33 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:06:48,383] [Log ] [33 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:48,387] [Log ] [33 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:48,391] [Log ] [33 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:06:48,395] [Log ] [33 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:06:48,399] [Log ] [33 ] [INFO ] - subch:0 pid:417 pcr
    [2016-01-28 19:06:48,403] [Log ] [33 ] [INFO ] - subch:0 pid:4F pmt
    [2016-01-28 19:06:48,405] [Log ] [33 ] [INFO ] - subch:0 pid:417 video type:H.264
    [2016-01-28 19:06:48,408] [Log ] [33 ] [INFO ] - subch:0 map pid:417 video type:H.264
    [2016-01-28 19:06:48,411] [Log ] [33 ] [INFO ] - subch:0 pid:BE7 audio lang:swe type:AC3
    [2016-01-28 19:06:48,414] [Log ] [33 ] [INFO ] - subch:0 map pid:BE7 audio lang:swe type:AC3
    [2016-01-28 19:06:48,416] [Log ] [33 ] [INFO ] - subch:0 pid:179A teletext type:6
    [2016-01-28 19:06:48,419] [Log ] [33 ] [INFO ] - subch:0 map pid:179A teletext type:6
    [2016-01-28 19:06:48,422] [Log ] [33 ] [INFO ] - ecm len:6 9 4 B 0 FB D0
    [2016-01-28 19:06:48,425] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 F E0 C0
    [2016-01-28 19:06:48,427] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 3E E0 C1
    [2016-01-28 19:06:48,430] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 40 E0 C2
    [2016-01-28 19:06:48,433] [Log ] [33 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :13
    [2016-01-28 19:06:48,436] [Log ] [33 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:06:48,439] [Log ] [33 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'TV4 HD' using plugin slot 1 of 1 avail.
    [2016-01-28 19:06:48,441] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 F E0 C0
    [2016-01-28 19:06:48,444] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 3E E0 C1
    [2016-01-28 19:06:48,447] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 40 E0 C2
    [2016-01-28 19:06:48,449] [Log ] [33 ] [INFO ] - EMM #0 CA:0x90F EMM:0xC0 ID:0x0
    [2016-01-28 19:06:48,452] [Log ] [33 ] [INFO ] - EMM #1 CA:0x93E EMM:0xC1 ID:0x0
    [2016-01-28 19:06:48,455] [Log ] [33 ] [INFO ] - EMM #2 CA:0x940 EMM:0xC2 ID:0x0
    [2016-01-28 19:06:48,458] [Log ] [33 ] [INFO ] - ecm len:6 9 4 B 0 FB D0
    [2016-01-28 19:06:48,461] [Log ] [33 ] [INFO ] - ECM #0 CA:0xB00 ECM:0x1BD0 ID:0x0
    [2016-01-28 19:06:48,464] [Log ] [33 ] [INFO ] - mdplug: tp_id:14(0xE) sid:1405(0x57D) pmt_id:79(0x4F)
    [2016-01-28 19:06:48,466] [Log ] [33 ] [INFO ] - mdplug: #0 CA_typ:2816(0xB00) ECM:7120(0x1BD0) EMM:0x0 provider:0(0x0)
    [2016-01-28 19:06:48,469] [Log ] [33 ] [INFO ] - mdplug: #1 CA_typ:2319(0x90F) ECM:0(0x0) EMM:0xC0 provider:0(0x0)
    [2016-01-28 19:06:48,472] [Log ] [33 ] [INFO ] - mdplug: #2 CA_typ:2366(0x93E) ECM:0(0x0) EMM:0xC1 provider:0(0x0)
    [2016-01-28 19:06:48,475] [Log ] [33 ] [INFO ] - mdplug: #3 CA_typ:2368(0x940) ECM:0(0x0) EMM:0xC2 provider:0(0x0)
    [2016-01-28 19:06:48,478] [Log ] [33 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:4 ECM_PID:7120(0x1BD0)
    [2016-01-28 19:06:48,481] [Log ] [33 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:06:48,484] [Log ] [33 ] [DEBUG] - WaitForPmt: PMT handling took 0,1370082 seconds.
    [2016-01-28 19:06:48,493] [Log ] [33 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:06:48,496] [Log ] [33 ] [INFO ] - klzzwxh:10057klzzwxh:10056klzzwxh:10055klzzwxh:10054klzzwxh:10053klzzwxh:10052klzzwxh:10051
    [2016-01-28 19:06:48,498] [Log ] [33 ] [INFO ] - ** SIGNAL LEVEL: 95, SIGNAL QUALITY: 83
    [2016-01-28 19:06:48,501] [Log ] [33 ] [INFO ] - klzzwxh:10050klzzwxh:10049klzzwxh:10048klzzwxh:10047klzzwxh:10046klzzwxh:10045klzzwxh:10044
    [2016-01-28 19:06:48,504] [Log ] [33 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:06:48,506] [Log ] [33 ] [INFO ] - user:Hometown add
    [2016-01-28 19:06:48,511] [Log ] [33 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:06:48,514] [Log ] [33 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:06:48,517] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:06:48,520] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:48,523] [Log ] [33 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:48,527] [Log ] [33 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:06:48,530] [Log ] [33 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:06:49,109] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:06:49,114] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:06:49,118] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,122] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,126] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,130] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,166] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:06:49,170] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:06:49,174] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,178] [Log ] [33 ] [INFO ] - card: WaitForFile - video and audio are seen after 0,6440375 seconds
    [2016-01-28 19:06:49,182] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,186] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:49,190] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,194] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=7, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:49,198] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:49
    [2016-01-28 19:06:49,202] [Log ] [33 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:06:49,207] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:06:49,212] [Log ] [33 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:06:49,216] [Log ] [38 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:06:49,223] [Log ] [38 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:06:50,780] [Log ] [38 ] [INFO ] - ChannelStates.DoSetChannelStates took 1564 msec
    [2016-01-28 19:06:53,100] [Log ] [38 ] [INFO ] - Not the time to fetch remote file yet
    [2016-01-28 19:06:54,617] [Log ] [3 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV3 HD 3505
    [2016-01-28 19:06:54,621] [Log ] [3 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:06:54,624] [Log ] [3 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:06:54,628] [Log ] [3 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:06:54,632] [Log ] [3 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,636] [Log ] [3 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:54,639] [Log ] [3 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:54,642] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:54,646] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:54,655] [Log ] [3 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:54,660] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 35 msec
    [2016-01-28 19:06:54,665] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:54,668] [Log ] [3 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:54,672] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 50 msec
    [2016-01-28 19:06:54,712] [Log ] [3 ] [INFO ] - Controller: StartTimeShifting TV3 HD 3505
    [2016-01-28 19:06:54,716] [Log ] [3 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:54,719] [Log ] [3 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:06:54,721] [Log ] [3 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:06:54,725] [Log ] [3 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:06:54,728] [Log ] [3 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,731] [Log ] [3 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:06:54,734] [Log ] [3 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:06:54,738] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:06:54,741] [Log ] [3 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:06:54,744] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    [2016-01-28 19:06:54,746] [Log ] [3 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:06:54,749] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 30 msec
    [2016-01-28 19:06:54,754] [Log ] [3 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=8, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,757] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:06:54,760] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:06:54,763] [Log ] [3 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:06:54,766] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:06:54,769] [Log ] [3 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3505, ticket=8, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:06:54,772] [Log ] [3 ] [INFO ] - card: CardTune 4 TV3 HD (S) Hometown:4:-1
    [2016-01-28 19:06:54,775] [Log ] [3 ] [INFO ] - card: Tune on card 4 to subchannel TV3 HD (S)
    [2016-01-28 19:06:54,778] [Log ] [3 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,786] [Log ] [3 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:06:54,789] [Log ] [3 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:06:54,792] [Log ] [3 ] [INFO ] - mdplug: FreeChannel TV4 HD
    [2016-01-28 19:06:54,795] [Log ] [3 ] [INFO ] - mdplug: usage counter for channel 'TV4 HD' is zero
    [2016-01-28 19:06:54,798] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:06:54,801] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:06:54,804] [Log ] [3 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:06:54,807] [Log ] [3 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,810] [Log ] [3 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:54,812] [Log ] [3 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:06:54,815] [Log ] [3 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:06:54,818] [Log ] [3 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:06:54,821] [Log ] [3 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:06:54,826] [Log ] [3 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:06:54,830] [Log ] [3 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:06:54,833] [Log ] [3 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:06:54,936] [Log ] [3 ] [INFO ] - dvb:Submiting tunerequest Channel:TV3 HD (S) subChannel:0
    [2016-01-28 19:06:54,940] [Log ] [3 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:06:54,944] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:06:54,948] [Log ] [3 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:06:54,952] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:06:55,144] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:06:55,149] [Log ] [3 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:06:55,153] [Log ] [3 ] [INFO ] - RunGraph
    [2016-01-28 19:06:55,157] [Log ] [3 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:06:55,161] [Log ] [3 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:06:55,165] [Log ] [3 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:06:55,169] [Log ] [3 ] [INFO ] - subch:0 SetupPmtGrabber:pid 18A sid:115E
    [2016-01-28 19:06:55,173] [Log ] [3 ] [INFO ] - subch:0 set pmt grabber pmt:18A sid:115E
    [2016-01-28 19:06:55,177] [Log ] [3 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:06:55,181] [Log ] [3 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:06:55,184] [Log ] [3 ] [DEBUG] - WaitForPMT: Waiting for PMT 18A
    [2016-01-28 19:06:55,187] [Log ] [29 ] [INFO ] - subch:OnCaReceived()
    [2016-01-28 19:06:55,346] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:18A ran:True dynamic:False
    [2016-01-28 19:06:55,350] [Log ] [3 ] [DEBUG] - WaitForPMT: Found PMT after 0,1660091 seconds.
    [2016-01-28 19:06:55,354] [Log ] [3 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:06:55,358] [Log ] [3 ] [INFO ] - subch:0 SendPmt:115E 115E FFFFFFFF 1C
    [2016-01-28 19:06:55,362] [Log ] [3 ] [INFO ] - Decode pmt
    [2016-01-28 19:06:55,366] [Log ] [3 ] [INFO ] - descr1 len:6 9 4 b 0 fb 76
    [2016-01-28 19:06:55,370] [Log ] [3 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:06:55,374] [Log ] [3 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:06:55,378] [Log ] [3 ] [INFO ] - subch:0 SendPMT version:28 len:53 4446
    [2016-01-28 19:06:55,382] [Log ] [3 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:06:55,387] [Log ] [3 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:06:55,391] [Log ] [3 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:06:55,393] [Log ] [3 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:06:55,396] [Log ] [3 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:06:55,399] [Log ] [3 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:06:55,401] [Log ] [3 ] [INFO ] - subch:0 pid:819 pcr
    [2016-01-28 19:06:55,404] [Log ] [3 ] [INFO ] - subch:0 pid:18A pmt
    [2016-01-28 19:06:55,407] [Log ] [3 ] [INFO ] - subch:0 pid:18BD teletext type:6
    [2016-01-28 19:06:55,410] [Log ] [3 ] [INFO ] - subch:0 map pid:18BD teletext type:6
    [2016-01-28 19:06:55,412] [Log ] [3 ] [INFO ] - subch:0 pid:819 video type:H.264
    [2016-01-28 19:06:55,415] [Log ] [3 ] [INFO ] - subch:0 map pid:819 video type:H.264
    [2016-01-28 19:06:55,418] [Log ] [3 ] [INFO ] - subch:0 pid:D14 audio lang:swe type:AC3
    [2016-01-28 19:06:55,421] [Log ] [3 ] [INFO ] - subch:0 map pid:D14 audio lang:swe type:AC3
    [2016-01-28 19:06:55,423] [Log ] [3 ] [INFO ] - ecm len:6 9 4 B 0 FB 76
    [2016-01-28 19:06:55,426] [Log ] [3 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:55,429] [Log ] [3 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :11
    [2016-01-28 19:06:55,432] [Log ] [3 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:06:55,434] [Log ] [3 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'TV3 HD (S)' using plugin slot 1 of 1 avail.
    [2016-01-28 19:06:55,437] [Log ] [3 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:06:55,440] [Log ] [3 ] klzzwxh:10000 - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    klzzwxh:10001 klzzwxh:10002 klzzwxh:10003 klzzwxh:10004 - ecm len:6 9 4 B 0 FB 76
    klzzwxh:10005 klzzwxh:10006 klzzwxh:10007 klzzwxh:10008 - ECM #0 CA:0xB00 ECM:0x1B76 ID:0x0
    klzzwxh:10009 klzzwxh:10010 klzzwxh:10011 klzzwxh:10012 - mdplug: tp_id:24(0x18) sid:4446(0x115E) pmt_id:394(0x18A)
    klzzwxh:10013 klzzwxh:10014 klzzwxh:10015 klzzwxh:10016 - mdplug: #0 CA_typ:2816(0xB00) ECM:7030(0x1B76) EMM:0x30 provider:0(0x0)
    klzzwxh:10017 klzzwxh:10018 klzzwxh:10019 klzzwxh:10020 - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7030(0x1B76)
    klzzwxh:10021 klzzwxh:10022 klzzwxh:10023 klzzwxh:10024 - subch:0 stop tif
    klzzwxh:10025 klzzwxh:10026 klzzwxh:10027 klzzwxh:10028 - WaitForPmt: PMT handling took 0,1070063 seconds.
    klzzwxh:10029 klzzwxh:10030 klzzwxh:10031 klzzwxh:10032 - card: Tuner locked: True
    klzzwxh:10033 klzzwxh:10034 klzzwxh:10035 klzzwxh:10036 - klzzwxh:10043klzzwxh:10042klzzwxh:10041klzzwxh:10040klzzwxh:10039klzzwxh:10038klzzwxh:10037
    [2016-01-28 19:06:55,478] [Log ] [3 ] [INFO ] - ** SIGNAL LEVEL: 94, SIGNAL QUALITY: 82
    [2016-01-28 19:06:55,481] [Log ] [3 ] [INFO ] - *******
    [2016-01-28 19:06:55,483] [Log ] [3 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:06:55,486] [Log ] [3 ] [INFO ] - user:Hometown add
    [2016-01-28 19:06:55,490] [Log ] [3 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:06:55,494] [Log ] [3 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:06:55,496] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:06:55,499] [Log ] [3 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:06:55,502] [Log ] [3 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:55,505] [Log ] [3 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:06:55,508] [Log ] [3 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:06:56,064] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:06:56,070] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:06:56,074] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,078] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,082] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,086] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,090] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,111] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:06:56,116] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:06:56,120] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,124] [Log ] [3 ] [INFO ] - card: WaitForFile - video and audio are seen after 0,6120357 seconds
    [2016-01-28 19:06:56,128] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,132] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,136] [Log ] [3 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:06:56,140] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,143] [Log ] [3 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=8, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:06:56,146] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:06:56
    [2016-01-28 19:06:56,148] [Log ] [3 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:06:56,152] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:06:56,155] [Log ] [3 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:06:56,159] [Log ] [19 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:06:56,165] [Log ] [19 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:06:57,600] [Log ] [19 ] [INFO ] - ChannelStates.DoSetChannelStates took 1442 msec
    [2016-01-28 19:07:00,026] [Log ] [3 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV4 HD 3476
    [2016-01-28 19:07:00,029] [Log ] [3 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:07:00,032] [Log ] [3 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:07:00,042] [Log ] [3 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:07:00,046] [Log ] [3 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,051] [Log ] [3 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:00,055] [Log ] [3 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:00,060] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:00,063] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:00,067] [Log ] [3 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:00,073] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 40 msec
    [2016-01-28 19:07:00,086] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:00,090] [Log ] [3 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:00,093] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 63 msec
    [2016-01-28 19:07:00,145] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting TV4 HD 3476
    [2016-01-28 19:07:00,148] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:00,151] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:07:00,154] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:07:00,158] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:07:00,161] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,164] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:00,167] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:00,170] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:00,173] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:00,176] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    [2016-01-28 19:07:00,179] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:00,182] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 30 msec
    [2016-01-28 19:07:00,187] [Log ] [33 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=9, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,190] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:00,193] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:00,196] [Log ] [33 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:07:00,199] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:07:00,202] [Log ] [33 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3476, ticket=9, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:07:00,205] [Log ] [33 ] [INFO ] - card: CardTune 4 TV4 HD Hometown:4:-1
    [2016-01-28 19:07:00,208] [Log ] [33 ] [INFO ] - card: Tune on card 4 to subchannel TV4 HD
    [2016-01-28 19:07:00,211] [Log ] [33 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,219] [Log ] [33 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:07:00,223] [Log ] [33 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:07:00,225] [Log ] [33 ] [INFO ] - mdplug: FreeChannel TV3 HD (S)
    [2016-01-28 19:07:00,228] [Log ] [33 ] [INFO ] - mdplug: usage counter for channel 'TV3 HD (S)' is zero
    [2016-01-28 19:07:00,231] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:00,234] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:07:00,237] [Log ] [33 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:07:00,240] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,242] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:00,245] [Log ] [33 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:07:00,248] [Log ] [33 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:07:00,251] [Log ] [33 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:07:00,253] [Log ] [33 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:07:00,258] [Log ] [33 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:07:00,262] [Log ] [33 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:07:00,265] [Log ] [33 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:07:00,369] [Log ] [33 ] [INFO ] - dvb:Submiting tunerequest Channel:TV4 HD subChannel:0
    [2016-01-28 19:07:00,373] [Log ] [33 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:07:00,377] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:07:00,381] [Log ] [33 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:07:00,385] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:07:00,577] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:07:00,582] [Log ] [33 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:07:00,586] [Log ] [33 ] [INFO ] - RunGraph
    [2016-01-28 19:07:00,591] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:07:00,595] [Log ] [33 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:07:00,599] [Log ] [33 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:07:00,603] [Log ] [33 ] [INFO ] - subch:0 SetupPmtGrabber:pid 4F sid:57D
    [2016-01-28 19:07:00,607] [Log ] [33 ] [INFO ] - subch:0 set pmt grabber pmt:4F sid:57D
    [2016-01-28 19:07:00,611] [Log ] [33 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:07:00,613] [Log ] [33 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:07:00,616] [Log ] [33 ] [DEBUG] - WaitForPMT: Waiting for PMT 4F
    [2016-01-28 19:07:00,746] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:4F ran:True dynamic:False
    [2016-01-28 19:07:00,750] [Log ] [33 ] [DEBUG] - WaitForPMT: Found PMT after 0,1340076 seconds.
    [2016-01-28 19:07:00,754] [Log ] [33 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:07:00,758] [Log ] [33 ] [INFO ] - subch:0 SendPmt:57D 57D FFFFFFFF 14
    [2016-01-28 19:07:00,762] [Log ] [33 ] [INFO ] - Decode pmt
    [2016-01-28 19:07:00,767] [Log ] [33 ] [INFO ] - descr1 len:6 9 4 b 0 fb d0
    [2016-01-28 19:07:00,771] [Log ] [33 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:07:00,775] [Log ] [33 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:07:00,779] [Log ] [33 ] [INFO ] - subch:0 SendPMT version:20 len:53 1405
    [2016-01-28 19:07:00,783] [Log ] [33 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:07:00,787] [Log ] [33 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:07:00,791] [Log ] [33 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:07:00,794] [Log ] [33 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:07:00,796] [Log ] [33 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:07:00,799] [Log ] [33 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:07:00,802] [Log ] [33 ] [INFO ] - subch:0 pid:417 pcr
    [2016-01-28 19:07:00,805] [Log ] [33 ] [INFO ] - subch:0 pid:4F pmt
    [2016-01-28 19:07:00,807] [Log ] [33 ] [INFO ] - subch:0 pid:417 video type:H.264
    [2016-01-28 19:07:00,810] [Log ] [33 ] [INFO ] - subch:0 map pid:417 video type:H.264
    [2016-01-28 19:07:00,813] [Log ] [33 ] [INFO ] - subch:0 pid:BE7 audio lang:swe type:AC3
    [2016-01-28 19:07:00,816] [Log ] [33 ] [INFO ] - subch:0 map pid:BE7 audio lang:swe type:AC3
    [2016-01-28 19:07:00,819] [Log ] [33 ] [INFO ] - subch:0 pid:179A teletext type:6
    [2016-01-28 19:07:00,821] [Log ] [33 ] [INFO ] - subch:0 map pid:179A teletext type:6
    [2016-01-28 19:07:00,824] [Log ] [33 ] [INFO ] - ecm len:6 9 4 B 0 FB D0
    [2016-01-28 19:07:00,827] [Log ] [33 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:07:00,830] [Log ] [33 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :11
    [2016-01-28 19:07:00,833] [Log ] [33 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:07:00,836] [Log ] [33 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'TV4 HD' using plugin slot 1 of 1 avail.
    [2016-01-28 19:07:00,838] [Log ] [33 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:07:00,841] [Log ] [33 ] [INFO ] - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    [2016-01-28 19:07:00,844] [Log ] [33 ] [INFO ] - ecm len:6 9 4 B 0 FB D0
    [2016-01-28 19:07:00,847] [Log ] [33 ] [INFO ] - ECM #0 CA:0xB00 ECM:0x1BD0 ID:0x0
    [2016-01-28 19:07:00,849] [Log ] [33 ] [INFO ] - mdplug: tp_id:14(0xE) sid:1405(0x57D) pmt_id:79(0x4F)
    [2016-01-28 19:07:00,852] [Log ] [33 ] [INFO ] - mdplug: #0 CA_typ:2816(0xB00) ECM:7120(0x1BD0) EMM:0x30 provider:0(0x0)
    [2016-01-28 19:07:00,856] [Log ] [33 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7120(0x1BD0)
    [2016-01-28 19:07:00,858] [Log ] [33 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:07:00,861] [Log ] [33 ] [DEBUG] - WaitForPmt: PMT handling took 0,1070055 seconds.
    [2016-01-28 19:07:00,870] [Log ] [33 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:07:00,873] [Log ] [33 ] [INFO ] - *******
    [2016-01-28 19:07:00,875] [Log ] [33 ] [INFO ] - ** SIGNAL LEVEL: 95, SIGNAL QUALITY: 83
    [2016-01-28 19:07:00,878] [Log ] [33 ] [INFO ] - *******
    [2016-01-28 19:07:00,881] [Log ] [33 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:07:00,883] [Log ] [33 ] [INFO ] - user:Hometown add
    [2016-01-28 19:07:00,887] [Log ] [33 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:07:00,891] [Log ] [33 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:07:00,894] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:07:00,897] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:00,901] [Log ] [33 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:00,904] [Log ] [33 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:07:00,907] [Log ] [33 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:07:01,483] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:07:01,488] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:07:01,492] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,496] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,500] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,504] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,508] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,587] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:07:01,591] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:07:01,595] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,599] [Log ] [33 ] [INFO ] - card: WaitForFile - video and audio are seen after 0,6880404 seconds
    [2016-01-28 19:07:01,603] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,607] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:01,611] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,615] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=9, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:01,619] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,623] [Log ] [33 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:07:01,627] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,631] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:07:01,634] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:01
    [2016-01-28 19:07:01,636] [Log ] [33 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:07:01,641] [Log ] [19 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:07:01,647] [Log ] [19 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:07:03,133] [Log ] [19 ] [INFO ] - ChannelStates.DoSetChannelStates took 1492 msec
    [2016-01-28 19:07:05,453] [Log ] [33 ] [INFO ] - Controller: TimeShiftingWouldUseCard Kanal 5 HD 3099
    [2016-01-28 19:07:05,457] [Log ] [33 ] [INFO ] - Controller: find free card for channel Kanal 5 HD
    [2016-01-28 19:07:05,464] [Log ] [33 ] [INFO ] - Controller: find card for channel Kanal 5 HD
    [2016-01-28 19:07:05,472] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for Kanal 5 HD
    [2016-01-28 19:07:05,477] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,480] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:05,483] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:05,487] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:05,492] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:05,498] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:05,502] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 38 msec
    [2016-01-28 19:07:05,512] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:05,515] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:05,518] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 61 msec
    [2016-01-28 19:07:05,547] [Log ] [3 ] [INFO ] - Controller: StartTimeShifting Kanal 5 HD 3099
    [2016-01-28 19:07:05,551] [Log ] [3 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:05,554] [Log ] [3 ] [INFO ] - Controller: find free card for channel Kanal 5 HD
    [2016-01-28 19:07:05,556] [Log ] [3 ] [INFO ] - Controller: find card for channel Kanal 5 HD
    [2016-01-28 19:07:05,560] [Log ] [3 ] [INFO ] - Controller: got 1 tuning details for Kanal 5 HD
    [2016-01-28 19:07:05,563] [Log ] [3 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,566] [Log ] [3 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:05,568] [Log ] [3 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:05,572] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:05,575] [Log ] [3 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:05,577] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 21 msec
    [2016-01-28 19:07:05,580] [Log ] [3 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:05,583] [Log ] [3 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 29 msec
    [2016-01-28 19:07:05,588] [Log ] [3 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=10, tuningdetails=DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,591] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:05,593] [Log ] [3 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:05,596] [Log ] [3 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:07:05,599] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:07:05,602] [Log ] [3 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3099, ticket=10, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:07:05,605] [Log ] [3 ] [INFO ] - card: CardTune 4 Kanal 5 HD (S) Hometown:4:-1
    [2016-01-28 19:07:05,608] [Log ] [3 ] [INFO ] - card: Tune on card 4 to subchannel Kanal 5 HD (S)
    [2016-01-28 19:07:05,611] [Log ] [3 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,619] [Log ] [3 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:07:05,622] [Log ] [3 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:07:05,625] [Log ] [3 ] [INFO ] - mdplug: FreeChannel TV4 HD
    [2016-01-28 19:07:05,628] [Log ] [3 ] [INFO ] - mdplug: usage counter for channel 'TV4 HD' is zero
    [2016-01-28 19:07:05,630] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:05,633] [Log ] [3 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:07:05,636] [Log ] [3 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:07:05,639] [Log ] [3 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,641] [Log ] [3 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:05,644] [Log ] [3 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:07:05,647] [Log ] [3 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:07:05,650] [Log ] [3 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:07:05,652] [Log ] [3 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:07:05,657] [Log ] [3 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:07:05,661] [Log ] [3 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:07:05,664] [Log ] [3 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:07:05,768] [Log ] [3 ] [INFO ] - dvb:Submiting tunerequest Channel:Kanal 5 HD (S) subChannel:0
    [2016-01-28 19:07:05,772] [Log ] [3 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:07:05,776] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:07:05,780] [Log ] [3 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:07:05,784] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:07:05,976] [Log ] [3 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:07:05,981] [Log ] [3 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:07:05,985] [Log ] [3 ] [INFO ] - RunGraph
    [2016-01-28 19:07:05,989] [Log ] [3 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:07:05,993] [Log ] [3 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:07:05,997] [Log ] [3 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:07:06,001] [Log ] [3 ] [INFO ] - subch:0 SetupPmtGrabber:pid 132 sid:1A91
    [2016-01-28 19:07:06,006] [Log ] [3 ] [INFO ] - subch:0 set pmt grabber pmt:132 sid:1A91
    [2016-01-28 19:07:06,010] [Log ] [3 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:07:06,013] [Log ] [3 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:07:06,015] [Log ] [3 ] [DEBUG] - WaitForPMT: Waiting for PMT 132
    [2016-01-28 19:07:06,127] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:132 ran:True dynamic:False
    [2016-01-28 19:07:06,131] [Log ] [3 ] [DEBUG] - WaitForPMT: Found PMT after 0,1160079 seconds.
    [2016-01-28 19:07:06,135] [Log ] [3 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:07:06,139] [Log ] [3 ] [INFO ] - subch:0 SendPmt:1A91 1A91 FFFFFFFF 12
    [2016-01-28 19:07:06,143] [Log ] [3 ] [INFO ] - Decode pmt
    [2016-01-28 19:07:06,147] [Log ] [3 ] [INFO ] - descr1 len:6 9 4 b 0 fb c0
    [2016-01-28 19:07:06,151] [Log ] [3 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:07:06,155] [Log ] [3 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:07:06,159] [Log ] [3 ] [INFO ] - subch:0 SendPMT version:18 len:50 6801
    [2016-01-28 19:07:06,162] [Log ] [3 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:07:06,165] [Log ] [3 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:07:06,168] [Log ] [3 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:07:06,170] [Log ] [3 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:07:06,173] [Log ] [3 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:07:06,176] [Log ] [3 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:07:06,178] [Log ] [3 ] [INFO ] - subch:0 pid:4E7 pcr
    [2016-01-28 19:07:06,181] [Log ] [3 ] [INFO ] - subch:0 pid:132 pmt
    [2016-01-28 19:07:06,184] [Log ] [3 ] [INFO ] - subch:0 pid:4E7 video type:H.264
    [2016-01-28 19:07:06,186] [Log ] [3 ] [INFO ] - subch:0 map pid:4E7 video type:H.264
    [2016-01-28 19:07:06,189] [Log ] [3 ] [INFO ] - subch:0 pid:CB7 audio lang:swe type:MPEG-2
    [2016-01-28 19:07:06,192] [Log ] [3 ] [INFO ] - subch:0 map pid:CB7 audio lang:swe type:MPEG-2
    [2016-01-28 19:07:06,194] [Log ] [3 ] [INFO ] - subch:0 pid:18A6 teletext type:6
    [2016-01-28 19:07:06,197] [Log ] [3 ] [INFO ] - subch:0 map pid:18A6 teletext type:6
    [2016-01-28 19:07:06,200] [Log ] [3 ] [INFO ] - ecm len:6 9 4 B 0 FB C0
    [2016-01-28 19:07:06,203] [Log ] [3 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:07:06,205] [Log ] [3 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :11
    [2016-01-28 19:07:06,208] [Log ] [3 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:07:06,211] [Log ] [3 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'Kanal 5 HD (S)' using plugin slot 1 of 1 avail.
    [2016-01-28 19:07:06,214] [Log ] [3 ] [INFO ] - emm len:6 9 4 B 0 E0 30
    [2016-01-28 19:07:06,217] [Log ] [3 ] [INFO ] - EMM #0 CA:0xB00 EMM:0x30 ID:0x0
    [2016-01-28 19:07:06,219] [Log ] [3 ] [INFO ] - ecm len:6 9 4 B 0 FB C0
    [2016-01-28 19:07:06,222] [Log ] [3 ] [INFO ] - ECM #0 CA:0xB00 ECM:0x1BC0 ID:0x0
    [2016-01-28 19:07:06,225] [Log ] [3 ] [INFO ] - mdplug: tp_id:67(0x43) sid:6801(0x1A91) pmt_id:306(0x132)
    [2016-01-28 19:07:06,227] [Log ] [3 ] [INFO ] - mdplug: #0 CA_typ:2816(0xB00) ECM:7104(0x1BC0) EMM:0x30 provider:0(0x0)
    [2016-01-28 19:07:06,231] [Log ] [3 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:1 ECM_PID:7104(0x1BC0)
    [2016-01-28 19:07:06,234] [Log ] [3 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:07:06,237] [Log ] [3 ] [DEBUG] - WaitForPmt: PMT handling took 0,1020054 seconds.
    [2016-01-28 19:07:06,239] [Log ] [29 ] [INFO ] - subch:OnCaReceived()
    [2016-01-28 19:07:06,245] [Log ] [3 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:07:06,248] [Log ] [3 ] [INFO ] - *******
    [2016-01-28 19:07:06,251] [Log ] [3 ] [INFO ] - ** SIGNAL LEVEL: 95, SIGNAL QUALITY: 82
    [2016-01-28 19:07:06,253] [Log ] [3 ] [INFO ] - *******
    [2016-01-28 19:07:06,256] [Log ] [3 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:07:06,259] [Log ] [3 ] [INFO ] - user:Hometown add
    [2016-01-28 19:07:06,263] [Log ] [3 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:07:06,266] [Log ] [3 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:07:06,269] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:07:06,272] [Log ] [3 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:06,275] [Log ] [3 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:06,278] [Log ] [3 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:07:06,281] [Log ] [3 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:07:06,940] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:07:06,944] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:07:06,948] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:06
    [2016-01-28 19:07:06,952] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:06
    [2016-01-28 19:07:06,956] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:06
    [2016-01-28 19:07:06,960] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:06
    [2016-01-28 19:07:06,964] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:06
    [2016-01-28 19:07:07,044] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:07:07,048] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:07:07,052] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,056] [Log ] [3 ] [INFO ] - card: WaitForFile - video and audio are seen after 0,7710441 seconds
    [2016-01-28 19:07:07,060] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,064] [Log ] [3 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:07,068] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,072] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,076] [Log ] [3 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=10, tuningdetails=DVBS:tv:Telenor Kanal 5 HD (S) Freq:10778000 ONID:70 TSID:67 SID:6801 PMT:0x132 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:07,080] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,084] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,088] [Log ] [3 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:07:07,091] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:07
    [2016-01-28 19:07:07,094] [Log ] [3 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:07:07,097] [Log ] [3 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:07:07,102] [Log ] [38 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:07:07,109] [Log ] [38 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:07:08,656] [Log ] [38 ] [INFO ] - ChannelStates.DoSetChannelStates took 1553 msec
    [2016-01-28 19:07:11,596] [Log ] [33 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV6 3086
    [2016-01-28 19:07:11,599] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV6
    [2016-01-28 19:07:11,602] [Log ] [33 ] [INFO ] - Controller: find card for channel TV6
    [2016-01-28 19:07:11,606] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV6
    [2016-01-28 19:07:11,609] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,616] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:11,621] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:11,629] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:11,634] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:11,637] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:11,640] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 38 msec
    [2016-01-28 19:07:11,643] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:11,650] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:11,655] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 55 msec
    [2016-01-28 19:07:11,682] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting TV6 3086
    [2016-01-28 19:07:11,685] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:11,688] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV6
    [2016-01-28 19:07:11,691] [Log ] [33 ] [INFO ] - Controller: find card for channel TV6
    [2016-01-28 19:07:11,694] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV6
    [2016-01-28 19:07:11,698] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,701] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:11,704] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:11,707] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:11,710] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:11,713] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 22 msec
    [2016-01-28 19:07:11,716] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:11,719] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 31 msec
    [2016-01-28 19:07:11,724] [Log ] [33 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=11, tuningdetails=DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,727] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:11,731] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:11,734] [Log ] [33 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:07:11,737] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:07:11,740] [Log ] [33 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3086, ticket=11, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:07:11,744] [Log ] [33 ] [INFO ] - card: CardTune 4 TV6 Hometown:4:-1
    [2016-01-28 19:07:11,747] [Log ] [33 ] [INFO ] - card: Tune on card 4 to subchannel TV6
    [2016-01-28 19:07:11,750] [Log ] [33 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,758] [Log ] [33 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:07:11,761] [Log ] [33 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:07:11,764] [Log ] [33 ] [INFO ] - mdplug: FreeChannel Kanal 5 HD (S)
    [2016-01-28 19:07:11,767] [Log ] [33 ] [INFO ] - mdplug: usage counter for channel 'Kanal 5 HD (S)' is zero
    [2016-01-28 19:07:11,770] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:11,773] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:07:11,776] [Log ] [33 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:07:11,778] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,781] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:11,784] [Log ] [33 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:07:11,787] [Log ] [33 ] [INFO ] - dvbs:channel modulation is set to ModQpsk
    [2016-01-28 19:07:11,790] [Log ] [33 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:07:11,793] [Log ] [33 ] [DEBUG] - Turbosight: set tone state, burst = DataBurst, 22 kHz = On
    [2016-01-28 19:07:11,797] [Log ] [33 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:07:11,801] [Log ] [33 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:07:11,804] [Log ] [33 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:07:11,908] [Log ] [33 ] [INFO ] - dvb:Submiting tunerequest Channel:TV6 subChannel:0
    [2016-01-28 19:07:11,912] [Log ] [33 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:07:11,916] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:07:11,920] [Log ] [33 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:07:11,924] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:07:12,116] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:07:12,121] [Log ] [33 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:07:12,125] [Log ] [33 ] [INFO ] - RunGraph
    [2016-01-28 19:07:12,129] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:07:12,133] [Log ] [33 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:07:12,137] [Log ] [33 ] [INFO ] - subch:0 Graph already running - WaitForPMT
    [2016-01-28 19:07:12,141] [Log ] [33 ] [INFO ] - subch:0 SetupPmtGrabber:pid 488 sid:488
    [2016-01-28 19:07:12,145] [Log ] [33 ] [INFO ] - subch:0 set pmt grabber pmt:488 sid:488
    [2016-01-28 19:07:12,149] [Log ] [33 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:07:12,153] [Log ] [33 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:07:12,157] [Log ] [33 ] [DEBUG] - WaitForPMT: Waiting for PMT 488
    [2016-01-28 19:07:12,199] [Log ] [29 ] [INFO ] - subch:OnCaReceived()
    [2016-01-28 19:07:12,227] [Log ] [29 ] [INFO ] - subch:0 OnPMTReceived() pmt:488 ran:True dynamic:False
    [2016-01-28 19:07:12,231] [Log ] [33 ] [DEBUG] - WaitForPMT: Found PMT after 0,0740044 seconds.
    [2016-01-28 19:07:12,235] [Log ] [33 ] [INFO ] - subch:0 SendPmt:CA found after 0 seconds
    [2016-01-28 19:07:12,239] [Log ] [33 ] [INFO ] - subch:0 SendPmt:488 488 FFFFFFFF 11
    [2016-01-28 19:07:12,243] [Log ] [33 ] [INFO ] - Decode pmt
    [2016-01-28 19:07:12,247] [Log ] [33 ] [INFO ] - descr2 pid:489 len:6 9 4 9 f e4 8d
    [2016-01-28 19:07:12,251] [Log ] [33 ] [INFO ] - descr2 pid:489 len:6 9 4 9 3e e0 98
    [2016-01-28 19:07:12,255] [Log ] [33 ] [INFO ] - descr2 pid:489 len:6 9 4 9 40 e1 92
    [2016-01-28 19:07:12,259] [Log ] [33 ] [INFO ] - Set descriptor data with length 7
    [2016-01-28 19:07:12,263] [Log ] [33 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:07:12,267] [Log ] [33 ] [INFO ] - descr2 pid:48A len:6 9 4 9 f e4 8d
    [2016-01-28 19:07:12,271] [Log ] [33 ] [INFO ] - descr2 pid:48A len:6 9 4 9 3e e0 98
    [2016-01-28 19:07:12,275] [Log ] [33 ] [INFO ] - descr2 pid:48A len:6 9 4 9 40 e1 92
    [2016-01-28 19:07:12,279] [Log ] [33 ] [INFO ] - Set descriptor data with length 6
    [2016-01-28 19:07:12,283] [Log ] [33 ] [INFO ] - descr2 pid:48B len:6 9 4 9 f e4 8d
    [2016-01-28 19:07:12,287] [Log ] [33 ] [INFO ] - descr2 pid:48B len:6 9 4 9 3e e0 98
    [2016-01-28 19:07:12,291] [Log ] [33 ] [INFO ] - descr2 pid:48B len:6 9 4 9 40 e1 92
    [2016-01-28 19:07:12,295] [Log ] [33 ] [INFO ] - subch:0 SendPMT version:17 len:109 1160
    [2016-01-28 19:07:12,299] [Log ] [33 ] [DEBUG] - Turbosight: send PMT to CAM, list action = Only, command = Descrambling
    [2016-01-28 19:07:12,303] [Log ] [33 ] [DEBUG] - Turbosight: CAM not available
    [2016-01-28 19:07:12,307] [Log ] [33 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:07:12,311] [Log ] [33 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:07:12,314] [Log ] [33 ] [INFO ] - subch:0 cam flags:False
    [2016-01-28 19:07:12,316] [Log ] [33 ] [INFO ] - subch:0 SetMpegPidMapping
    [2016-01-28 19:07:12,319] [Log ] [33 ] [INFO ] - subch:0 pid:489 pcr
    [2016-01-28 19:07:12,322] [Log ] [33 ] [INFO ] - subch:0 pid:488 pmt
    [2016-01-28 19:07:12,325] [Log ] [33 ] [INFO ] - subch:0 pid:489 video type:MPEG-2
    [2016-01-28 19:07:12,327] [Log ] [33 ] [INFO ] - subch:0 map pid:489 video type:MPEG-2
    [2016-01-28 19:07:12,330] [Log ] [33 ] [INFO ] - subch:0 pid:48E teletext type:6
    [2016-01-28 19:07:12,333] [Log ] [33 ] [INFO ] - subch:0 map pid:48E teletext type:6
    [2016-01-28 19:07:12,335] [Log ] [33 ] [INFO ] - subch:0 pid:48A audio lang:swe type:MPEG-1
    [2016-01-28 19:07:12,338] [Log ] [33 ] [INFO ] - subch:0 map pid:48A audio lang:swe type:MPEG-1
    [2016-01-28 19:07:12,341] [Log ] [33 ] [INFO ] - subch:0 pid:48B audio lang:syn type:MPEG-1
    [2016-01-28 19:07:12,344] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,346] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,349] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,352] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,355] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,357] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,360] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,363] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,366] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,368] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 F E0 C0
    [2016-01-28 19:07:12,371] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 3E E0 C1
    [2016-01-28 19:07:12,374] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 40 E0 C2
    [2016-01-28 19:07:12,377] [Log ] [33 ] [INFO ] - Number of HWPIDS that needs to be sent to tuner :16
    [2016-01-28 19:07:12,380] [Log ] [33 ] [INFO ] - mdplug: SetChannel nr of currently decoding channels 0.
    [2016-01-28 19:07:12,382] [Log ] [33 ] [INFO ] - mdplug: SetChannel starting decryption on channel 'TV6' using plugin slot 1 of 1 avail.
    [2016-01-28 19:07:12,385] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 F E0 C0
    [2016-01-28 19:07:12,388] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 3E E0 C1
    [2016-01-28 19:07:12,391] [Log ] [33 ] [INFO ] - emm len:6 9 4 9 40 E0 C2
    [2016-01-28 19:07:12,393] [Log ] [33 ] [INFO ] - EMM #0 CA:0x90F EMM:0xC0 ID:0x0
    [2016-01-28 19:07:12,396] [Log ] [33 ] [INFO ] - EMM #1 CA:0x93E EMM:0xC1 ID:0x0
    [2016-01-28 19:07:12,399] [Log ] [33 ] [INFO ] - EMM #2 CA:0x940 EMM:0xC2 ID:0x0
    [2016-01-28 19:07:12,401] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,404] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,407] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,410] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,412] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,415] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,418] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 F E4 8D
    [2016-01-28 19:07:12,421] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 3E E0 98
    [2016-01-28 19:07:12,423] [Log ] [33 ] [INFO ] - ecm len:6 9 4 9 40 E1 92
    [2016-01-28 19:07:12,426] [Log ] [33 ] [INFO ] - ECM #0 CA:0x90F ECM:0x48D ID:0x0
    [2016-01-28 19:07:12,429] [Log ] [33 ] [INFO ] - ECM #1 CA:0x93E ECM:0x98 ID:0x0
    [2016-01-28 19:07:12,432] [Log ] [33 ] [INFO ] - ECM #2 CA:0x940 ECM:0x192 ID:0x0
    [2016-01-28 19:07:12,435] [Log ] [33 ] [INFO ] - mdplug: tp_id:3(0x3) sid:1160(0x488) pmt_id:1160(0x488)
    [2016-01-28 19:07:12,437] [Log ] [33 ] [INFO ] - mdplug: #0 CA_typ:2319(0x90F) ECM:1165(0x48D) EMM:0xC0 provider:0(0x0)
    [2016-01-28 19:07:12,440] [Log ] [33 ] [INFO ] - mdplug: #1 CA_typ:2366(0x93E) ECM:152(0x98) EMM:0xC1 provider:0(0x0)
    [2016-01-28 19:07:12,443] [Log ] [33 ] [INFO ] - mdplug: #2 CA_typ:2368(0x940) ECM:402(0x192) EMM:0xC2 provider:0(0x0)
    [2016-01-28 19:07:12,446] [Log ] [33 ] [INFO ] - mdplug: Send channel change to MDAPI filter Ca_Id:0 CA_Nr:3 ECM_PID:1165(0x48D)
    [2016-01-28 19:07:12,449] [Log ] [33 ] [INFO ] - subch:0 stop tif
    [2016-01-28 19:07:12,452] [Log ] [33 ] [DEBUG] - WaitForPmt: PMT handling took 0,2170126 seconds.
    [2016-01-28 19:07:12,460] [Log ] [33 ] [DEBUG] - card: Tuner locked: True
    [2016-01-28 19:07:12,464] [Log ] [33 ] [INFO ] - *******
    [2016-01-28 19:07:12,466] [Log ] [33 ] [INFO ] - ** SIGNAL LEVEL: 94, SIGNAL QUALITY: 80
    [2016-01-28 19:07:12,469] [Log ] [33 ] [INFO ] - *******
    [2016-01-28 19:07:12,472] [Log ] [33 ] [DEBUG] - card: tuned user: Hometown subchannel: 0
    [2016-01-28 19:07:12,474] [Log ] [33 ] [INFO ] - user:Hometown add
    [2016-01-28 19:07:12,479] [Log ] [33 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:07:12,482] [Log ] [33 ] [DEBUG] - Timeshifting started - Recordings=0 TimeShiftingActive=True
    [2016-01-28 19:07:12,485] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartTimeShifting
    [2016-01-28 19:07:12,488] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:12,491] [Log ] [33 ] [INFO ] - card: StartTimeShifting 4 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:12,494] [Log ] [33 ] [INFO ] - card: CAM enabled : True
    [2016-01-28 19:07:12,497] [Log ] [33 ] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2016-01-28 19:07:14,428] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:07:14,433] [Log ] [29 ] [INFO ] - audioVideoEventHandler Audio
    [2016-01-28 19:07:14,437] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,441] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,445] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,449] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,453] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,505] [Log ] [29 ] [INFO ] - PID seen - type = Video
    [2016-01-28 19:07:14,509] [Log ] [29 ] [INFO ] - audioVideoEventHandler Video
    [2016-01-28 19:07:14,513] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,517] [Log ] [33 ] [INFO ] - card: WaitForFile - video and audio are seen after 2,0161166 seconds
    [2016-01-28 19:07:14,521] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,525] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting started on card:4 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:14,529] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,532] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=11, tuningdetails=DVBS:tv:Viasat TV6 Freq:12054000 ONID:86 TSID:3 SID:1160 PMT:0x488 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModQpsk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleB band:Universal Pilot:NotDefined RollOff:NotDefined
    [2016-01-28 19:07:14,535] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,538] [Log ] [33 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:07:14,541] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,543] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:07:14,546] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,549] [Log ] [33 ] [INFO ] - control2:Hometown 4 0
    [2016-01-28 19:07:14,551] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,555] [Log ] [29 ] [INFO ] - video last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,560] [Log ] [19 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:07:14,569] [Log ] [19 ] [INFO ] - ChannelStates.GetAllTimeshiftingAndRecordingChannels took 0 msec
    [2016-01-28 19:07:14,574] [Log ] [29 ] [INFO ] - PID seen - type = Audio
    [2016-01-28 19:07:14,577] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,586] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,589] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,591] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:14,594] [Log ] [29 ] [INFO ] - audio last seen at 2016-01-28 19:07:14
    [2016-01-28 19:07:16,077] [Log ] [19 ] [INFO ] - ChannelStates.DoSetChannelStates took 1524 msec
    [2016-01-28 19:07:20,512] [Log ] [33 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV12 HD 3121
    [2016-01-28 19:07:20,518] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV12 HD
    [2016-01-28 19:07:20,522] [Log ] [33 ] [INFO ] - Controller: find card for channel TV12 HD
    [2016-01-28 19:07:20,529] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV12 HD
    [2016-01-28 19:07:20,532] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,535] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:20,538] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:20,542] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:20,545] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:20,549] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:20,552] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 29 msec
    [2016-01-28 19:07:20,554] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:20,558] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:20,562] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 43 msec
    [2016-01-28 19:07:20,593] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting TV12 HD 3121
    [2016-01-28 19:07:20,596] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:07:20,599] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV12 HD
    [2016-01-28 19:07:20,602] [Log ] [33 ] [INFO ] - Controller: find card for channel TV12 HD
    [2016-01-28 19:07:20,605] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV12 HD
    [2016-01-28 19:07:20,609] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,611] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:07:20,614] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:07:20,618] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:07:20,621] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:07:20,623] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 21 msec
    [2016-01-28 19:07:20,626] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:07:20,629] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 29 msec
    [2016-01-28 19:07:20,634] [Log ] [33 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=12, tuningdetails=DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,637] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:07:20,640] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:07:20,643] [Log ] [33 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:07:20,646] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:07:20,649] [Log ] [33 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3121, ticket=12, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:07:20,652] [Log ] [33 ] [INFO ] - card: CardTune 4 TV12 HD Hometown:4:-1
    [2016-01-28 19:07:20,655] [Log ] [33 ] [INFO ] - card: Tune on card 4 to subchannel TV12 HD
    [2016-01-28 19:07:20,658] [Log ] [33 ] [DEBUG] - card: user: Hometown:4:0 tune DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,666] [Log ] [33 ] [DEBUG] - card: to different transponder
    [2016-01-28 19:07:20,669] [Log ] [33 ] [INFO ] - FreeSubChannel MD: freeing sub channel : 0
    [2016-01-28 19:07:20,672] [Log ] [33 ] [INFO ] - mdplug: FreeChannel TV6
    [2016-01-28 19:07:20,675] [Log ] [33 ] [INFO ] - mdplug: usage counter for channel 'TV6' is zero
    [2016-01-28 19:07:20,678] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:20,682] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:07:20,685] [Log ] [33 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:07:20,688] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,691] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:20,693] [Log ] [33 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:07:20,696] [Log ] [33 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:07:20,699] [Log ] [33 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:07:20,701] [Log ] [33 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:07:20,706] [Log ] [33 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:07:20,710] [Log ] [33 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:07:20,713] [Log ] [33 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:07:20,817] [Log ] [33 ] [INFO ] - dvb:Submiting tunerequest Channel:TV12 HD subChannel:0
    [2016-01-28 19:07:20,821] [Log ] [33 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:07:20,825] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:07:20,828] [Log ] [33 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:07:20,832] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:07:23,409] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:07:23,414] [Log ] [33 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:07:23,418] [Log ] [33 ] [INFO ] - RunGraph
    [2016-01-28 19:07:23,422] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:07:23,447] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:07:23,471] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:07:23,496] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:07:23,521] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:07:25,457] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal could not lock onto channel - no signal or bad signal
    [2016-01-28 19:07:25,461] [Log ] [33 ] [INFO ] - FreeSubChannel MD: tried to free non existing sub channel : 0
    [2016-01-28 19:07:25,465] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:25,469] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel :0 - is timeshifting (skipped)
    [2016-01-28 19:07:25,473] [Log ] [33 ] [INFO ] - card2:Hometown 4 0
    [2016-01-28 19:07:25,478] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=12, tuningdetails=DVBS:tv:Telenor TV12 HD Freq:10903000 ONID:70 TSID:69 SID:7092 PMT:0x1BC0 FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearV InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:07:25,482] [Log ] [33 ] [INFO ] - Controller: Hometown 4 0
    [2016-01-28 19:07:25,486] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:07:25,490] [Log ] [33 ] [DEBUG] - Timeshifting stopped - Recordings=0 TimeShiftingActive=False
    [2016-01-28 19:07:25,494] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndTimeShifting
    [2016-01-28 19:07:25,498] [Log ] [33 ] [INFO ] - Controller: StopTimeShifting 4
    [2016-01-28 19:07:25,503] [Log ] [33 ] [DEBUG] - CardTuner.RequestCardStopReservation: placed reservation with id=13, user=Hometown
    [2016-01-28 19:07:25,609] [Log ] [33 ] [DEBUG] - CardTuner.Stop: ticket id=13, found=True
    [2016-01-28 19:07:25,613] [Log ] [33 ] [INFO ] - Stop cardid=4, ticket=13, tunestate=Idle, stopstate=Stopping
    [2016-01-28 19:07:25,617] [Log ] [33 ] [INFO ] - card TBS 6982 DVBS/S2 Tuner B: StopTimeShifting user:Hometown sub:0
    [2016-01-28 19:07:25,620] [Log ] [33 ] [DEBUG] - card not IDLE - removing user: Hometown
    [2016-01-28 19:07:25,625] [Log ] [33 ] [DEBUG] - usermanagement.RemoveUser: Hometown, subch: 0 of 1, card: 4
    [2016-01-28 19:07:25,629] [Log ] [33 ] [INFO ] - user:Hometown remove
    [2016-01-28 19:07:25,633] [Log ] [33 ] [INFO ] - subch:0-0 tswriter StopTimeshifting...
    [2016-01-28 19:07:25,637] [Log ] [33 ] [INFO ] - FreeSubChannel MD: tried to free non existing sub channel : 0
    [2016-01-28 19:07:25,641] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:07:25,645] [Log ] [33 ] [INFO ] - DVB subch:0 Decompose()
    [2016-01-28 19:07:25,649] [Log ] [33 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
    [2016-01-28 19:07:25,653] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
    [2016-01-28 19:07:25,657] [Log ] [33 ] [INFO ] - dvb:StopGraph called
    [2016-01-28 19:07:25,660] [Log ] [33 ] [INFO ] - tvcard:FreeAllSubChannels
    [2016-01-28 19:07:25,663] [Log ] [33 ] [INFO ] - mdplug: FreeAllChannels
    [2016-01-28 19:07:25,665] [Log ] [33 ] [INFO ] - dvb:StopGraph
    [2016-01-28 19:07:25,717] [Log ] [33 ] [INFO ] - debug: IMediaControl stopped! hr = 0x0 :)
    [2016-01-28 19:07:25,721] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:25,724] [Log ] [33 ] [INFO ] - dvb:StopGraph called
    [2016-01-28 19:07:25,727] [Log ] [33 ] [INFO ] - tvcard:FreeAllSubChannels
    [2016-01-28 19:07:25,730] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts.tsbuffer
    [2016-01-28 19:07:25,733] [Log ] [33 ] [INFO ] - mdplug: FreeAllChannels
    [2016-01-28 19:07:25,736] [Log ] [33 ] [INFO ] - dvb:StopGraph filterstate already stopped, returning.
    [2016-01-28 19:07:25,738] [Log ] [33 ] [INFO ] - user:Hometown remove
    [2016-01-28 19:07:25,741] [Log ] [33 ] [DEBUG] - CardReservation.RemoveStopTicket: removed STOP reservation with id=13
    [2016-01-28 19:07:25,744] [Log ] [33 ] [INFO ] - Controller:Timeshifting stopped on card:4
    [2016-01-28 19:07:25,746] [Log ] [33 ] [INFO ] - RTSP: remove stream stream4.0
    [2016-01-28 19:07:25,752] [Log ] [33 ] [INFO ] - Controller: epg start
    [2016-01-28 19:07:25,811] [Log ] [19 ] [DEBUG] - Controller: DoSetChannelStates for 1033 channels
    [2016-01-28 19:07:25,814] [Log ] [33 ] [INFO ] - Controller: Timeshifting failed, no more cards available.
    [2016-01-28 19:07:25,817] [Log ] [19 ] [INFO ] - ChannelStates.DoSetChannelStates took 3 msec
    [2016-01-28 19:07:25,820] [Log ] [33 ] [INFO ] - Controller: epg start
    [2016-01-28 19:07:30,735] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts
    [2016-01-28 19:07:30,740] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts.tsbuffer
    [2016-01-28 19:07:30,744] [Log ] [TS_File_Cleanup] [INFO ] - card: deleted file C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts.tsbuffer
    [2016-01-28 19:07:30,748] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts.tsbuffer1.ts
    [2016-01-28 19:07:30,760] [Log ] [TS_File_Cleanup] [INFO ] - card: deleted file C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live4-0.ts.tsbuffer1.ts
    [2016-01-28 19:07:53,101] [Log ] [22 ] [INFO ] - Not the time to fetch remote file yet
    [2016-01-28 19:08:15,988] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:08:15,991] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:08:15,995] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:08:15,998] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,001] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:16,003] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:16,007] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:16,010] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:16,013] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:16,015] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 24 msec
    [2016-01-28 19:08:16,018] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:16,021] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:16,023] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 35 msec
    [2016-01-28 19:08:16,027] [Log ] [33 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV4 HD 3476
    [2016-01-28 19:08:16,030] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:08:16,033] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:08:16,036] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:08:16,039] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,042] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:16,045] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:16,048] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:16,051] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:16,054] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:16,056] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 23 msec
    [2016-01-28 19:08:16,059] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:16,062] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:16,064] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 34 msec
    [2016-01-28 19:08:16,067] [Log ] [33 ] [DEBUG] - CiMenuSupported called cardid 4
    [2016-01-28 19:08:16,070] [Log ] [33 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:08:16,073] [Log ] [33 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:08:16,075] [Log ] [33 ] [DEBUG] - CiMenuSupported card TBS 6982 DVBS/S2 Tuner B supported: False
    [2016-01-28 19:08:16,078] [Log ] [33 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:08:16,081] [Log ] [33 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:08:16,085] [Log ] [33 ] [INFO ] - Controller: StartTimeShifting TV4 HD 3476
    [2016-01-28 19:08:16,089] [Log ] [33 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:08:16,092] [Log ] [33 ] [INFO ] - Controller: find free card for channel TV4 HD
    [2016-01-28 19:08:16,094] [Log ] [33 ] [INFO ] - Controller: find card for channel TV4 HD
    [2016-01-28 19:08:16,098] [Log ] [33 ] [INFO ] - Controller: got 1 tuning details for TV4 HD
    [2016-01-28 19:08:16,101] [Log ] [33 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,104] [Log ] [33 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:16,106] [Log ] [33 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:16,110] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:16,113] [Log ] [33 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:16,115] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 20 msec
    [2016-01-28 19:08:16,118] [Log ] [33 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:16,121] [Log ] [33 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 28 msec
    [2016-01-28 19:08:16,125] [Log ] [33 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=14, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,128] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:16,131] [Log ] [33 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:16,134] [Log ] [33 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:08:16,136] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:08:16,139] [Log ] [33 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3476, ticket=14, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:08:16,142] [Log ] [33 ] [INFO ] - card: CardTune 4 TV4 HD Hometown:4:-1
    [2016-01-28 19:08:16,145] [Log ] [33 ] [INFO ] - card: Tune on card 4 to subchannel TV4 HD
    [2016-01-28 19:08:16,148] [Log ] [33 ] [DEBUG] - card: user: Hometown:4:-1 tune DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,155] [Log ] [33 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:08:16,158] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,161] [Log ] [33 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:16,163] [Log ] [33 ] [INFO ] - dvb:GetNewSubChannel:0 #0
    [2016-01-28 19:08:16,166] [Log ] [33 ] [INFO ] - TvDvbChannel ctor new subchIndex:0
    [2016-01-28 19:08:16,169] [Log ] [33 ] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
    [2016-01-28 19:08:16,172] [Log ] [33 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:08:16,174] [Log ] [33 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:08:16,177] [Log ] [33 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:08:16,180] [Log ] [33 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:08:16,184] [Log ] [33 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:08:16,188] [Log ] [33 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:08:16,191] [Log ] [33 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:08:16,295] [Log ] [33 ] [INFO ] - dvb:Submiting tunerequest Channel:TV4 HD subChannel:0
    [2016-01-28 19:08:16,299] [Log ] [33 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:08:16,303] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:08:16,307] [Log ] [33 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:08:16,311] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:08:16,314] [Log ] [33 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:08:16,318] [Log ] [33 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:08:16,323] [Log ] [33 ] [INFO ] - RunGraph
    [2016-01-28 19:08:16,327] [Log ] [33 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:08:16,330] [Log ] [33 ] [INFO ] - dvb: RunGraph
    [2016-01-28 19:08:16,556] [Log ] [33 ] [INFO ] - dvb: LockInOnSignal ok
    [2016-01-28 19:08:16,561] [Log ] [33 ] [INFO ] - subch:0 OnGraphStarted
    [2016-01-28 19:08:16,565] [Log ] [33 ] [INFO ] - subch:0 SetupPmtGrabber:pid 4F sid:57D
    [2016-01-28 19:08:16,569] [Log ] [33 ] [INFO ] - subch:0 set pmt grabber pmt:4F sid:57D
    [2016-01-28 19:08:16,572] [Log ] [33 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:08:16,575] [Log ] [33 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:08:16,577] [Log ] [33 ] [DEBUG] - WaitForPMT: Waiting for PMT 4F
    [2016-01-28 19:08:26,581] [Log ] [33 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10,0035791 seconds. Increase the PMT timeout value?
    [2016-01-28 19:08:26,585] [Log ] [33 ] [DEBUG] - Setting to 0 to search for new PMT.
    [2016-01-28 19:08:26,589] [Log ] [33 ] [INFO ] - subch:0 SetupPmtGrabber:pid 0 sid:57D
    [2016-01-28 19:08:26,593] [Log ] [33 ] [INFO ] - subch:0 set pmt grabber pmt:0 sid:57D
    [2016-01-28 19:08:26,597] [Log ] [33 ] [INFO ] - subch:0 set ca grabber
    [2016-01-28 19:08:26,601] [Log ] [33 ] [DEBUG] - TimeShifter.OnAfterTune: resetting audio/video time
    [2016-01-28 19:08:26,604] [Log ] [33 ] [DEBUG] - WaitForPMT: Waiting for PMT 0
    [2016-01-28 19:08:36,608] [Log ] [33 ] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10,0045784 seconds. Increase the PMT timeout value?
    [2016-01-28 19:08:36,612] [Log ] [33 ] [DEBUG] - Setting to 0 to search for new PMT.
    [2016-01-28 19:08:36,616] [Log ] [33 ] [INFO ] - FreeSubChannel MD: tried to free non existing sub channel : 0
    [2016-01-28 19:08:36,620] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:08:36,624] [Log ] [33 ] [INFO ] - DVB subch:0 Decompose()
    [2016-01-28 19:08:36,628] [Log ] [33 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
    [2016-01-28 19:08:36,632] [Log ] [33 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
    [2016-01-28 19:08:36,635] [Log ] [33 ] [INFO ] - dvb:StopGraph called
    [2016-01-28 19:08:36,639] [Log ] [33 ] [INFO ] - tvcard:FreeAllSubChannels
    [2016-01-28 19:08:36,642] [Log ] [33 ] [INFO ] - mdplug: FreeAllChannels
    [2016-01-28 19:08:36,644] [Log ] [33 ] [INFO ] - dvb:StopGraph
    [2016-01-28 19:08:36,703] [Log ] [33 ] [INFO ] - debug: IMediaControl stopped! hr = 0x0 :)
    [2016-01-28 19:08:36,707] [Log ] [33 ] [INFO ] - card2:Hometown 4 -1
    [2016-01-28 19:08:36,710] [Log ] [33 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=14, tuningdetails=DVBS:tv:Telenor TV4 HD Freq:10934000 ONID:70 TSID:14 SID:1405 PMT:0x4F FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:36,713] [Log ] [33 ] [INFO ] - card: SignalTuneEvent card: 4 / subch: 0
    [2016-01-28 19:08:36,716] [Log ] [33 ] [INFO ] - Controller: Hometown 4 -1
    [2016-01-28 19:08:36,719] [Log ] [33 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:08:36,722] [Log ] [33 ] [INFO ] - Controller: Timeshifting failed, no more cards available.
    [2016-01-28 19:08:36,725] [Log ] [33 ] [INFO ] - Controller: epg start
    [2016-01-28 19:08:46,027] [Log ] [4 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:08:46,030] [Log ] [4 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:08:46,035] [Log ] [4 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:08:46,038] [Log ] [4 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,041] [Log ] [4 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:46,043] [Log ] [4 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:46,047] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:46,050] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:46,053] [Log ] [4 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:46,055] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 24 msec
    [2016-01-28 19:08:46,058] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:46,061] [Log ] [4 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:46,063] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 36 msec
    [2016-01-28 19:08:46,066] [Log ] [4 ] [INFO ] - Controller: TimeShiftingWouldUseCard TV3 HD 3505
    [2016-01-28 19:08:46,070] [Log ] [4 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:08:46,072] [Log ] [4 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:08:46,076] [Log ] [4 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:08:46,079] [Log ] [4 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,082] [Log ] [4 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:46,084] [Log ] [4 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:46,088] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:46,091] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:46,093] [Log ] [4 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:46,096] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 23 msec
    [2016-01-28 19:08:46,099] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:46,101] [Log ] [4 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:46,104] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 34 msec
    [2016-01-28 19:08:46,107] [Log ] [4 ] [DEBUG] - CiMenuSupported called cardid 4
    [2016-01-28 19:08:46,110] [Log ] [4 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:08:46,112] [Log ] [4 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:08:46,115] [Log ] [4 ] [DEBUG] - CiMenuSupported card TBS 6982 DVBS/S2 Tuner B supported: False
    [2016-01-28 19:08:46,118] [Log ] [4 ] [DEBUG] - Turbosight: is CAM ready
    [2016-01-28 19:08:46,120] [Log ] [4 ] [DEBUG] - Turbosight: interface not opened
    [2016-01-28 19:08:46,124] [Log ] [4 ] [INFO ] - Controller: StartTimeShifting TV3 HD 3505
    [2016-01-28 19:08:46,127] [Log ] [4 ] [INFO ] - Controller: epg stop
    [2016-01-28 19:08:46,129] [Log ] [4 ] [INFO ] - Controller: find free card for channel TV3 HD
    [2016-01-28 19:08:46,132] [Log ] [4 ] [INFO ] - Controller: find card for channel TV3 HD
    [2016-01-28 19:08:46,135] [Log ] [4 ] [INFO ] - Controller: got 1 tuning details for TV3 HD
    [2016-01-28 19:08:46,138] [Log ] [4 ] [INFO ] - Controller: channel #1 DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,141] [Log ] [4 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
    [2016-01-28 19:08:46,144] [Log ] [4 ] [INFO ] - Controller: card:5 type:DvbS is disabled
    [2016-01-28 19:08:46,147] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS can tune to channel
    [2016-01-28 19:08:46,150] [Log ] [4 ] [INFO ] - Controller: found 1 card(s) for channel
    [2016-01-28 19:08:46,153] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 20 msec
    [2016-01-28 19:08:46,155] [Log ] [4 ] [INFO ] - Controller: found 1 free card(s)
    [2016-01-28 19:08:46,158] [Log ] [4 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 28 msec
    [2016-01-28 19:08:46,162] [Log ] [4 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=15, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,165] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS users: 0
    [2016-01-28 19:08:46,168] [Log ] [4 ] [INFO ] - Controller: card:4 type:DvbS is available
    [2016-01-28 19:08:46,171] [Log ] [4 ] [INFO ] - Controller: try max 1 of 1 cards for timeshifting
    [2016-01-28 19:08:46,174] [Log ] [4 ] [DEBUG] - TVServerKodi: OnTvServerEvent: StartZapChannel
    [2016-01-28 19:08:46,176] [Log ] [4 ] [DEBUG] - CardReservationBase: tvcard=4, user=Hometown, dbChannel=3505, ticket=15, tunestate=Tuning, stopstate=Idle
    [2016-01-28 19:08:46,179] [Log ] [4 ] [INFO ] - card: CardTune 4 TV3 HD (S) Hometown:4:-1
    [2016-01-28 19:08:46,182] [Log ] [4 ] [INFO ] - card: Tune on card 4 to subchannel TV3 HD (S)
    [2016-01-28 19:08:46,185] [Log ] [4 ] [DEBUG] - card: user: Hometown:4:-1 tune DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,192] [Log ] [4 ] [DEBUG] - TimeShifter.OnBeforeTune: resetting audio/video events
    [2016-01-28 19:08:46,195] [Log ] [4 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,198] [Log ] [4 ] [INFO ] - dvbs: Tune:DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:46,201] [Log ] [4 ] [INFO ] - dvb:GetNewSubChannel:0 #0
    [2016-01-28 19:08:46,204] [Log ] [4 ] [INFO ] - TvDvbChannel ctor new subchIndex:0
    [2016-01-28 19:08:46,206] [Log ] [4 ] [INFO ] - card: AddTuneEvent card: 4 / subch: 0
    [2016-01-28 19:08:46,209] [Log ] [4 ] [INFO ] - LNB low:9750 hi:10600 switch:11700
    [2016-01-28 19:08:46,212] [Log ] [4 ] [INFO ] - dvbs:channel modulation is set to Mod8Psk
    [2016-01-28 19:08:46,214] [Log ] [4 ] [INFO ] - dvbs:channel FECRate is set to Rate3_4
    [2016-01-28 19:08:46,217] [Log ] [4 ] [DEBUG] - Turbosight: set tone state, burst = ToneBurst, 22 kHz = Off
    [2016-01-28 19:08:46,222] [Log ] [4 ] [DEBUG] - Turbosight: burst result = success
    [2016-01-28 19:08:46,226] [Log ] [4 ] [DEBUG] - Turbosight: 22 kHz result = success
    [2016-01-28 19:08:46,228] [Log ] [4 ] [INFO ] - Turbosight: Set DVB-S2
    [2016-01-28 19:08:46,332] [Log ] [4 ] [INFO ] - dvb:Submiting tunerequest Channel:TV3 HD (S) subChannel:0
    [2016-01-28 19:08:46,336] [Log ] [4 ] [INFO ] - dvb:using existing subchannel:0
    [2016-01-28 19:08:46,340] [Log ] [4 ] [INFO ] - dvb:Submit tunerequest size:1 new:0
    [2016-01-28 19:08:46,344] [Log ] [4 ] [INFO ] - subch:0 OnBeforeTune
    [2016-01-28 19:08:46,347] [Log ] [4 ] [INFO ] - dvb:Submit tunerequest calling put_TuneRequest
    [2016-01-28 19:08:46,351] [Log ] [4 ] [INFO ] - dvb:Submit tunerequest done calling put_TuneRequest
    [2016-01-28 19:08:46,355] [Log ] [4 ] [INFO ] - subch:0 OnAfterTune
    [2016-01-28 19:08:46,359] [Log ] [4 ] [INFO ] - RunGraph
    [2016-01-28 19:08:46,362] [Log ] [4 ] [INFO ] - subch:0 OnGraphStart
    [2016-01-28 19:08:46,365] [Log ] [4 ] [INFO ] - dvb: RunGraph
    [2016-01-28 19:08:48,974] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:08:48,999] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:08:49,023] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:08:49,047] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:08:49,072] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal waiting 20ms
    [2016-01-28 19:08:51,008] [Log ] [4 ] [INFO ] - dvb: LockInOnSignal could not lock onto channel - no signal or bad signal
    [2016-01-28 19:08:51,012] [Log ] [4 ] [INFO ] - FreeSubChannel MD: tried to free non existing sub channel : 0
    [2016-01-28 19:08:51,016] [Log ] [4 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
    [2016-01-28 19:08:51,020] [Log ] [4 ] [INFO ] - DVB subch:0 Decompose()
    [2016-01-28 19:08:51,024] [Log ] [4 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
    [2016-01-28 19:08:51,027] [Log ] [4 ] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
    [2016-01-28 19:08:51,031] [Log ] [4 ] [INFO ] - dvb:StopGraph called
    [2016-01-28 19:08:51,035] [Log ] [4 ] [INFO ] - tvcard:FreeAllSubChannels
    [2016-01-28 19:08:51,039] [Log ] [4 ] [INFO ] - mdplug: FreeAllChannels
    [2016-01-28 19:08:51,042] [Log ] [4 ] [INFO ] - dvb:StopGraph
    [2016-01-28 19:08:51,151] [Log ] [4 ] [INFO ] - debug: IMediaControl stopped! hr = 0x0 :)
    [2016-01-28 19:08:51,154] [Log ] [4 ] [INFO ] - card2:Hometown 4 -1
    [2016-01-28 19:08:51,159] [Log ] [4 ] [DEBUG] - CardReservation.RemoveTuneTicket: removed reservation with id=15, tuningdetails=DVBS:tv:Telenor TV3 HD (S) Freq:11293000 ONID:70 TSID:24 SID:4446 PMT:0x18A FTA:False LCN:10000 SymbolRate:25000 Modulation:Mod8Psk Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:SimpleA band:Universal Pilot:On RollOff:ThirtyFive
    [2016-01-28 19:08:51,162] [Log ] [4 ] [INFO ] - card: SignalTuneEvent card: 4 / subch: 0
    [2016-01-28 19:08:51,164] [Log ] [4 ] [INFO ] - Controller: Hometown 4 -1
    [2016-01-28 19:08:51,167] [Log ] [4 ] [DEBUG] - TVServerKodi: OnTvServerEvent: EndZapChannel
    [2016-01-28 19:08:51,170] [Log ] [4 ] [INFO ] - Controller: Timeshifting failed, no more cards available.
    [2016-01-28 19:08:51,172] [Log ] [4 ] [INFO ] - Controller: epg start
    [2016-01-28 19:08:53,101] [Log ] [40 ] [INFO ] - Not the time to fetch remote file yet

     

  • PlusPlus

    PlusPlus - 2016-01-28

    Most of all it is not MDAPI problem. With default settings MDAPI may only cause No Audio/Video error and with any settings it can't cause No signal error.

     

  • tce

    tce - 2016-02-25

    Hello,

    I have almost the same issue.
    When I change channel, randomly, MP freeze (client & server)
    But if I kill MDAPI processes (from task manager), MDAPI restart automatically and it is not frozen anymore.
    Here is the mdapi log.
    We can see that the freeze occurs at 23:00:44 ACamd.dll : CPlugin::AddChannel

     
    mdapi_plus.log

  • PlusPlus

    PlusPlus - 2016-02-29

    Hi, the log is incomplete, please archive all the log files in the directory and specify exact time when the frozen occurred

     

  • tce

    tce - 2016-03-20

    Hi
    Sorry for the delay

    Here are all the logs (mdapi, acamd, mediaportal and tuner)
    Freeze occurs at 20/03/2016 14:43:53
    I wait 2 minutes before killing mdapi exec's

    Thanks !

     
    mdapi.7z

Log in to post a comment.

Want the latest updates on software, tech news, and AI?
Get latest updates about software, tech news, and AI from SourceForge directly in your inbox once a month.