search

jasmin-j / vdr-plugin-ddci2

Support for stand alone CI by Digital Devices for VDR 2.1.7 and higher.
GNU General Public License v2.0
5 stars 2 forks source link

Can't write packet VDR CamSlot for CI adapter #2

Closed emilsvennesson closed 7 years ago

emilsvennesson commented 7 years ago

Hi! I just upgraded to VDR 2.3.3 and version 1.0.1 of this plugin. I was previously on VDR 2.2 and an older version of this plugin that worked fine, but I am having issues with the new version.

-- Logs begin at Sun 2016-01-03 15:38:35 CET, end at Fri 2017-03-31 18:53:01 CEST. --
mar 31 18:19:21 vdr systemd[1]: Starting Video Disk Recorder...
mar 31 18:19:21 vdr vdr[572]: [572] VDR version 2.3.3 started
mar 31 18:19:21 vdr vdr[572]: [572] switched to user 'vdr'
mar 31 18:19:21 vdr vdr[572]: [572] codeset is 'UTF-8' - known
mar 31 18:19:21 vdr vdr[572]: [572] override character table is 'ISO-8859-15'
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-ddci2.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-devstatus.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-restfulapi.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Port has been set to 8002!
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Ip has been set to 0.0.0.0!
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: can not add webapp 'webapp'! Path '/var/lib/vdr/restfulapi/webapp' does not exist!
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: trying to parse command line arguments
mar 31 18:19:21 vdr vdr[572]: [572] RESTful-API Settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrmanager.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrtva.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] loading plugin: /usr/lib/vdr/plugins/libvdr-vnsiserver.so.2.3.3
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/setup.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/sources.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/diseqc.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/scr.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/channels.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/timers.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/svdrphosts.conf
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/keymacros.conf
mar 31 18:19:21 vdr vdr[572]: [572] DVB API version is 0x050A (VDR was built with 0x050A)
mar 31 18:19:21 vdr vdr[572]: [572] frontend 0/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
mar 31 18:19:21 vdr vdr[572]: [572] frontend 1/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
mar 31 18:19:21 vdr vdr[572]: [572] found 2 DVB devices
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: ddci2 (1.0.1): External Digital Devices CI-Adapter
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: devstatus (0.4.1): Status of dvb devices
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: restfulapi (0.2.6.1): Offers a RESTful-API to retrieve data from VDR
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: vdrmanager (0.14): VDR-Manager plugin
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: vdrtva (0.3.6): Series Record plugin
mar 31 18:19:21 vdr vdr[572]: [572] initializing plugin: vnsiserver (1.5.2): VDR-Network-Streaming-Interface (VNSI) Server
mar 31 18:19:21 vdr vdr[572]: [572] setting primary device to 1
mar 31 18:19:21 vdr vdr[572]: [572] device 1 has no MPEG decoder
mar 31 18:19:21 vdr vdr[572]: [572] setting current skin to "lcars"
mar 31 18:19:21 vdr vdr[572]: [572] loading /var/lib/vdr/themes/lcars-default.theme
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: ddci2
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Inf: plugin version 1.0.1 initializing (compiled for VDR version 2.3.3)
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: Debug logging mask 0x0001
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter3/ci0'
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter2/ci0'
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Inf: found 2 DD CI adapters
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Inf: Creating DdCiAdapter 0 (/dev/dvb/adapter2/ca0)
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter2/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) Reset slot 0
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Inf: Creating DdCiAdapter 1 (/dev/dvb/adapter3/ca0)
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter3/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 created
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) Reset slot 0
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
mar 31 18:19:21 vdr vdr[572]: [572] DDCI-Inf: plugin started
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: devstatus
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: restfulapi
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Used settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: The cached files will be loaded from /var/cache/vdr/plugins/restfulapi!
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: The config dir is /var/cache/vdr/plugins/restfulapi!
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: found 19 files in /*.
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: found 19 files in /*.
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Webapp file types config file /var/lib/vdr/plugins/restfulapi/webapp_file_types.conf found.
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi finished.
mar 31 18:19:21 vdr vdr[572]: [572] restfulapi: using sync directory: /var/cache/vdr/plugins/restfulapi/sync
mar 31 18:19:21 vdr vdr[572]: [572] create server
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: vdrmanager
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: vdrtva
mar 31 18:19:21 vdr vdr[572]: [591] [vdrmanager] created non SSL server socket on port 6420
mar 31 18:19:21 vdr vdr[572]: [572] vdrtva: series links file not found
mar 31 18:19:21 vdr vdr[572]: [572] starting plugin: vnsiserver
mar 31 18:19:21 vdr vdr[572]: [572] VNSI: Starting vnsi server at port=34890
mar 31 18:19:21 vdr vdr[572]: [591] [vdrmanager] SSL key files /etc/vdr/plugins/vdrmanager/vdrmanager.pem and /etc/vdr/plugins/vdrmanager/vdrmanager.pem can't be read. SSL disabled.
mar 31 18:19:21 vdr vdr[572]: [572] VNSI: VNSI Server started
mar 31 18:19:21 vdr vdr[572]: [572] VNSI: Channel streaming timeout: 10 seconds
mar 31 18:19:21 vdr vdr[572]: [592] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
mar 31 18:19:21 vdr vdr[572]: [592] VNSI: Client with ID 0 connected: 192.168.1.7:47810
mar 31 18:19:21 vdr vdr[572]: [601] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
mar 31 18:19:21 vdr vdr[572]: [581] CAM 1: module present
mar 31 18:19:21 vdr vdr[572]: [585] CAM 2: module present
mar 31 18:19:21 vdr vdr[572]: [592] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
mar 31 18:19:21 vdr vdr[572]: [592] VNSI: Client with ID 1 connected: 192.168.1.1:35716
mar 31 18:19:21 vdr vdr[572]: [602] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
mar 31 18:19:21 vdr vdr[572]: [599] VNSI: Requesting clients to reload recordings list
mar 31 18:19:21 vdr vdr[572]: [581] CAM 1: module ready
mar 31 18:19:21 vdr vdr[572]: [585] CAM 2: module ready
mar 31 18:19:22 vdr vdr[572]: [592] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
mar 31 18:19:22 vdr vdr[572]: [592] VNSI: Client with ID 2 connected: 192.168.1.4:51900
mar 31 18:19:22 vdr vdr[572]: [603] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
mar 31 18:19:24 vdr vdr[572]: [581] CAM 1: CryptoGuard CAM, 01, CAFE, BABE
mar 31 18:19:24 vdr vdr[572]: [585] CAM 2: CryptoGuard CAM, 01, CAFE, BABE
mar 31 18:19:29 vdr vdr[572]: [572] switching to channel 4 (TV4 HD)
mar 31 18:19:29 vdr systemd[1]: Started Video Disk Recorder.
mar 31 18:19:29 vdr vdr[572]: [604] SVDRP listening on port 6419/tcp
mar 31 18:19:29 vdr vdr[572]: [572] ERROR: no OSD provider available - using dummy OSD!
mar 31 18:19:29 vdr vdr[572]: [572] vdrtva: Data capture started
mar 31 18:19:30 vdr vdr[572]: [599] VNSI: Requesting clients to reload channel list
mar 31 18:19:35 vdr vdr[572]: [599] VNSI: Requesting clients to reload channel list
mar 31 18:19:57 vdr vdr[572]: [592] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
mar 31 18:19:57 vdr vdr[572]: [592] VNSI: Client with ID 3 connected: 192.168.1.5:58841
mar 31 18:19:57 vdr vdr[572]: [606] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
mar 31 18:20:01 vdr vdr[572]: [592] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
mar 31 18:20:01 vdr vdr[572]: [592] VNSI: Client with ID 4 connected: 192.168.1.5:58895
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: LiveStreamer::Close - close
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: close video input ...
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: allocated timeshift buffer with size: 500000000
mar 31 18:20:01 vdr vdr[572]: [607] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: Successfully found following device: 0xa6fec0 (1) for receiving, priority=0
mar 31 18:20:01 vdr vdr[572]: [607] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:01 vdr vdr[572]: [607] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: Dummy receiver (0x7f207000b6d0) activated
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: activate live receiver: 1
mar 31 18:20:01 vdr vdr[572]: [607] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: Successfully switched to channel 4 - TV4 HD
mar 31 18:20:01 vdr vdr[572]: [607] VNSI: Started streaming of channel TV4 HD (timeout 10 seconds)
mar 31 18:20:01 vdr vdr[572]: [610] VNSI: Created stream for pid=1581 and type=8
mar 31 18:20:01 vdr vdr[572]: [610] VNSI: Created stream for pid=1584 and type=1
mar 31 18:20:01 vdr vdr[572]: [610] VNSI: Created stream for pid=1582 and type=12
mar 31 18:20:01 vdr vdr[572]: [572] ERROR: no OSD provider available - using dummy OSD!
mar 31 18:20:11 vdr vdr[572]: [610] VNSI: Channel: no data 16
mar 31 18:20:21 vdr vdr[572]: [610] VNSI: Channel: no data 16
mar 31 18:20:31 vdr vdr[572]: [610] VNSI: Channel: no data 16
mar 31 18:20:32 vdr vdr[572]: [608] VNSI: activate live receiver: 0
mar 31 18:20:32 vdr vdr[572]: [608] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:32 vdr vdr[572]: [608] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: re-tuning...
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: close video input ...
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: Dummy receiver (0x7f207000b6d0) deactivated
mar 31 18:20:32 vdr vdr[572]: [610] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: Successfully found following device: 0xa6fec0 (1) for receiving, priority=0
mar 31 18:20:32 vdr vdr[572]: [610] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:32 vdr vdr[572]: [610] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: Dummy receiver (0xaa87c0) activated
mar 31 18:20:32 vdr vdr[572]: [610] VNSI: activate live receiver: 1
mar 31 18:20:32 vdr vdr[572]: [610] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:36 vdr vdr[572]: [613] VNSI: activate live receiver: 0
mar 31 18:20:36 vdr vdr[572]: [613] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
mar 31 18:20:36 vdr vdr[572]: [613] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: re-tuning...
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: close video input ...
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: Dummy receiver (0xaa87c0) deactivated
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: re-tuning...
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: close video input ...
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: re-tuning...
mar 31 18:20:36 vdr vdr[572]: [610] VNSI: close video input ...
mar 31 18:20:36 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:36 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:37 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:37 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:37 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:37 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:38 vdr vdr[572]: [588] DDCI-Err: Can't write packet VDR CamSlot for CI adapter (/dev/dvb/adapter3/ca0)
mar 31 18:20:38 vdr vdr[572]: [610] VNSI: re-tuning...
mar 31 18:20:38 vdr vdr[572]: [610] VNSI: close video input ...
[root@vdr ~]# dmesg | grep DDBridge
[    4.156917] DDBridge: Digital Devices PCIE bridge driver 0.9.28, Copyright (C) 2010-16 Digital Devices GmbH
[    4.159871] DDBridge: device name: Digital Devices Cine CT V7 DVB adapter
[    4.159888] DDBridge: HW 00010002 REGMAP 00010004
[    4.159901] DDBridge: link 0 vendor dd01 device 0006 subvendor dd01 subdevice 0032
[    4.279174] DDBridge: Port 0: Link 0, Link Port 0 (TAB 1): DUAL DVB-C2T2 CXD2843
[    4.280047] DDBridge: XO2 ID 03
[    4.280202] DDBridge: Port 1: DuoFlex CI 1.0
[    4.394110] DDBridge: Port 1: Link 0, Link Port 1 (TAB 2): DuoFlex CI
[    4.395507] DDBridge: Port 2: Link 0, Link Port 2 (TAB 3): DuoFlex CI_B
[    4.396501] DDBridge: Port 3: Link 0, Link Port 3 (TAB 4): NO MODULE
[    4.397733] DDBridge: 0 netstream channels
[    4.397735] DVB: registering new adapter (DDBridge)
[    4.397736] DVB: registering new adapter (DDBridge)
[    4.397737] DVB: registering new adapter (DDBridge)
[    4.397737] DVB: registering new adapter (DDBridge)
[   10.024357] DDBridge: slot_reset_xo2
[   10.024491] DDBridge: slot_reset_xo2
[   10.525271] DDBridge: slot_ts_enable_xo2
[   10.525389] DDBridge: slot_ts_enable_xo2
[   47.736939] DDBridge: slot_shutdown_xo2
[   47.737419] DDBridge: slot_reset_xo2
[   47.737924] DDBridge: slot_shutdown_xo2
[   47.739010] DDBridge: slot_reset_xo2
[   48.241902] DDBridge: slot_ts_enable_xo2
[   48.242005] DDBridge: slot_ts_enable_xo2
[   77.537821] DDBridge: IA 3 119936 00000007
[   78.941177] DDBridge: IA 3 122496 00000007
[   81.892153] DDBridge: IA 5 124416 00000007
[  103.735322] DDBridge: IA 1 124928 00000007
[  105.338267] DDBridge: IA 2 2048 00000007
[  106.935805] DDBridge: IA 2 4992 00000007
[  108.737707] DDBridge: IA 2 8448 00000007
[  110.534599] DDBridge: IA 2 11648 00000007
[  112.339010] DDBridge: IA 2 14976 00000007
[  113.842535] DDBridge: IA 2 17792 00000007
[root@vdr ~]# dmesg | grep dvb_ca
[   10.525496] dvb_ca adapter 2: DVB CAM detected and initialised successfully
[   10.525598] dvb_ca adapter 3: DVB CAM detected and initialised successfully
[   48.242108] dvb_ca adapter 2: DVB CAM detected and initialised successfully
[   48.242209] dvb_ca adapter 3: DVB CAM detected and initialised successfully

Please tell me if you're in need of any more info!

jasmin-j commented 7 years ago

Very strange ... we tested it on my VDR and also on the one from Klaus. We didn't see such an behaviour. But we both have used a single CAM only. I have seen that you have two CAMs connected and you are using the new dual CI IF. Hmm.... so you even can't remove one. The problem is, that my Octopus Duo CI is currently mounted in my operational VDR, which still runs with VDR 2.2.0. I need to think how to reproduce that ... .

BR, Jasmin

jasmin-j commented 7 years ago

Another user had the same problem. I answered in the German (!) VDR forum. Maybe you can understand a little bit or use Google translate.

The important thing is the buffer size change: -> in "ddcirecvbuf.h" and "ddcitsrecv.h" set BUF_NUM to 10000 If this doesn't help your processor is simply too slow, I guess.

jasmin-j commented 7 years ago

If the buffer size increase doesn't help, you can try changing the write mode. In file "ddci.h" set "DDCI_DECRYPT_MORE" to '0'.

If this helps, then your CAMs are really old or at least very slow.

Please give me feedback, so that I know if I need to add a parameter to the plugin.

jasmin-j commented 7 years ago

I just commited version 1.0.2. Please try if it fixes your problem and then close this issue.

emilsvennesson commented 7 years ago

@jasmin-j Thanks a lot for taking a look at this so quickly! I will try the new version and report back.

I doubt this is a CPU problem though, seeing as I run VDR in a VM using a Xeon E3-1240.

emilsvennesson commented 7 years ago

Unfortunately, it's still a no go with the new version. :-/ The 'Can't write packet VDR CamSlot for CI adapter' errors seems to be gone but tuning to the channel still fails.

apr 01 23:23:23 vdr systemd[1]: Starting Video Disk Recorder...
apr 01 23:23:23 vdr vdr[13315]: [13315] VDR version 2.3.3 started
apr 01 23:23:23 vdr vdr[13315]: [13315] switched to user 'vdr'
apr 01 23:23:23 vdr vdr[13315]: [13315] codeset is 'UTF-8' - known
apr 01 23:23:23 vdr vdr[13315]: [13315] override character table is 'ISO-8859-15'
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-ddci2.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-devstatus.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-restfulapi.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Port has been set to 8002!
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Ip has been set to 0.0.0.0!
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: can not add webapp 'webapp'! Path '/var/lib/vdr/restfulapi/webapp' does not exist!
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: trying to parse command line arguments
apr 01 23:23:23 vdr vdr[13315]: [13315] RESTful-API Settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrmanager.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrtva.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] loading plugin: /usr/lib/vdr/plugins/libvdr-vnsiserver.so.2.3.3
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/setup.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/sources.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/diseqc.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/scr.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/channels.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/timers.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/svdrphosts.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/keymacros.conf
apr 01 23:23:23 vdr vdr[13315]: [13315] DVB API version is 0x050A (VDR was built with 0x050A)
apr 01 23:23:23 vdr vdr[13315]: [13315] frontend 0/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 01 23:23:23 vdr vdr[13315]: [13315] frontend 1/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 01 23:23:23 vdr vdr[13315]: [13315] found 2 DVB devices
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: ddci2 (1.0.2): External Digital Devices CI-Adapter
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: devstatus (0.4.1): Status of dvb devices
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: restfulapi (0.2.6.1): Offers a RESTful-API to retrieve data from VDR
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: vdrmanager (0.14): VDR-Manager plugin
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: vdrtva (0.3.6): Series Record plugin
apr 01 23:23:23 vdr vdr[13315]: [13315] initializing plugin: vnsiserver (1.5.2): VDR-Network-Streaming-Interface (VNSI) Server
apr 01 23:23:23 vdr vdr[13315]: [13315] setting primary device to 1
apr 01 23:23:23 vdr vdr[13315]: [13315] device 1 has no MPEG decoder
apr 01 23:23:23 vdr vdr[13315]: [13315] setting current skin to "lcars"
apr 01 23:23:23 vdr vdr[13315]: [13315] loading /var/lib/vdr/themes/lcars-default.theme
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: ddci2
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Inf: plugin version 1.0.2 initializing (compiled for VDR version 2.3.3)
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: Debug logging mask 0x1001
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: Buffer size 1500 packets
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: Sleep timer 100ms
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter3/ci0'
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter2/ci0'
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Inf: found 2 DD CI adapters
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Inf: Creating DdCiAdapter 0 (/dev/dvb/adapter2/ca0)
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter2/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) Reset slot 0
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Inf: Creating DdCiAdapter 1 (/dev/dvb/adapter3/ca0)
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter3/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 created
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) Reset slot 0
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 01 23:23:23 vdr vdr[13315]: [13315] DDCI-Inf: plugin started
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: devstatus
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: restfulapi
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Used settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: The cached files will be loaded from /var/cache/vdr/plugins/restfulapi!
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: The config dir is /var/cache/vdr/plugins/restfulapi!
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: found 19 files in /*.
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: found 19 files in /*.
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Webapp file types config file /var/lib/vdr/plugins/restfulapi/webapp_file_types.conf found.
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi finished.
apr 01 23:23:23 vdr vdr[13315]: [13315] restfulapi: using sync directory: /var/cache/vdr/plugins/restfulapi/sync
apr 01 23:23:23 vdr vdr[13315]: [13315] create server
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: vdrmanager
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: vdrtva
apr 01 23:23:23 vdr vdr[13315]: [13315] vdrtva: series links file not found
apr 01 23:23:23 vdr vdr[13315]: [13315] starting plugin: vnsiserver
apr 01 23:23:23 vdr vdr[13315]: [13315] VNSI: Starting vnsi server at port=34890
apr 01 23:23:23 vdr vdr[13315]: [13315] VNSI: VNSI Server started
apr 01 23:23:23 vdr vdr[13315]: [13315] VNSI: Channel streaming timeout: 10 seconds
apr 01 23:23:23 vdr vdr[13315]: [13331] [vdrmanager] created non SSL server socket on port 6420
apr 01 23:23:23 vdr vdr[13315]: [13331] [vdrmanager] SSL key files /etc/vdr/plugins/vdrmanager/vdrmanager.pem and /etc/vdr/plugins/vdrmanager/vdrmanager.pem can't be read. SSL disabled.
apr 01 23:23:23 vdr vdr[13315]: [13332] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 01 23:23:23 vdr vdr[13315]: [13332] VNSI: Client with ID 0 connected: 192.168.1.7:57630
apr 01 23:23:23 vdr vdr[13315]: [13344] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 01 23:23:23 vdr vdr[13315]: [13332] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 01 23:23:23 vdr vdr[13315]: [13332] VNSI: Client with ID 1 connected: 192.168.1.171:57250
apr 01 23:23:23 vdr vdr[13315]: [13324] CAM 1: module present
apr 01 23:23:23 vdr vdr[13315]: [13345] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 01 23:23:23 vdr vdr[13315]: [13328] CAM 2: module present
apr 01 23:23:23 vdr vdr[13315]: [13332] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 01 23:23:23 vdr vdr[13315]: [13332] VNSI: Client with ID 2 connected: 192.168.1.1:61190
apr 01 23:23:23 vdr vdr[13315]: [13346] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 01 23:23:23 vdr vdr[13315]: [13332] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 01 23:23:23 vdr vdr[13315]: [13332] VNSI: Client with ID 3 connected: 192.168.1.5:52848
apr 01 23:23:23 vdr vdr[13315]: [13347] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 01 23:23:23 vdr vdr[13315]: [13333] VNSI: Requesting clients to reload recordings list
apr 01 23:23:24 vdr vdr[13315]: [13324] CAM 1: module ready
apr 01 23:23:24 vdr vdr[13315]: [13328] CAM 2: module ready
apr 01 23:23:26 vdr vdr[13315]: [13324] CAM 1: CryptoGuard CAM, 01, CAFE, BABE
apr 01 23:23:26 vdr vdr[13315]: [13328] CAM 2: CryptoGuard CAM, 01, CAFE, BABE
apr 01 23:23:31 vdr vdr[13315]: [13315] switching to channel 4 (TV4 HD)
apr 01 23:23:31 vdr systemd[1]: Started Video Disk Recorder.
apr 01 23:23:31 vdr vdr[13315]: [13348] SVDRP listening on port 6419/tcp
apr 01 23:23:31 vdr vdr[13315]: [13315] ERROR: no OSD provider available - using dummy OSD!
apr 01 23:23:31 vdr vdr[13315]: [13315] vdrtva: Data capture started
apr 01 23:23:32 vdr vdr[13315]: [13333] VNSI: Requesting clients to reload channel list
apr 01 23:23:33 vdr vdr[13315]: [13326] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):4701, rd:4704
apr 01 23:23:33 vdr vdr[13315]: [13342] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 CAM buff wr(CAM ->):4701, rd:4704
apr 01 23:23:37 vdr vdr[13315]: [13333] VNSI: Requesting clients to reload channel list
apr 01 23:23:45 vdr vdr[13315]: [13332] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 01 23:23:45 vdr vdr[13315]: [13332] VNSI: Client with ID 4 connected: 192.168.1.5:52887
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: LiveStreamer::Close - close
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: close video input ...
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: allocated timeshift buffer with size: 500000000
apr 01 23:23:45 vdr vdr[13315]: [13350] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: Successfully found following device: 0x1558ee0 (1) for receiving, priority=0
apr 01 23:23:45 vdr vdr[13315]: [13350] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 01 23:23:45 vdr vdr[13315]: [13350] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: Dummy receiver (0x7f9490003f10) activated
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: activate live receiver: 1
apr 01 23:23:45 vdr vdr[13315]: [13350] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: Successfully switched to channel 4 - TV4 HD
apr 01 23:23:45 vdr vdr[13315]: [13350] VNSI: Started streaming of channel TV4 HD (timeout 10 seconds)
apr 01 23:23:46 vdr vdr[13315]: [13315] ERROR: no OSD provider available - using dummy OSD!
apr 01 23:23:46 vdr vdr[13315]: [13353] VNSI: Created stream for pid=1581 and type=8
apr 01 23:23:46 vdr vdr[13315]: [13353] VNSI: Created stream for pid=1584 and type=1
apr 01 23:23:46 vdr vdr[13315]: [13353] VNSI: Created stream for pid=1582 and type=12
apr 01 23:23:53 vdr vdr[13315]: [13342] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 CAM buff wr(CAM ->):3074, rd:1576
apr 01 23:23:53 vdr vdr[13315]: [13341] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 CAM buff rd(-> CAM):43000, wr:43482
apr 01 23:23:55 vdr vdr[13315]: [13353] VNSI: Channel: no data 16
apr 01 23:24:03 vdr vdr[13315]: [13342] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 CAM buff wr(CAM ->):3176, rd:1678
apr 01 23:24:03 vdr vdr[13315]: [13341] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 CAM buff rd(-> CAM):91062, wr:91610
apr 01 23:24:05 vdr vdr[13315]: [13353] VNSI: Channel: no data 16
apr 01 23:24:13 vdr vdr[13315]: [13342] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 CAM buff wr(CAM ->):3277, rd:1779
apr 01 23:24:13 vdr vdr[13315]: [13341] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 CAM buff rd(-> CAM):139433, wr:139974
apr 01 23:24:15 vdr vdr[13315]: [13353] VNSI: Channel: no data 16
apr 01 23:24:16 vdr vdr[13315]: [13351] VNSI: activate live receiver: 0
apr 01 23:24:16 vdr vdr[13315]: [13351] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 01 23:24:16 vdr vdr[13315]: [13351] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: re-tuning...
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: close video input ...
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: Dummy receiver (0x7f9490003f10) deactivated
apr 01 23:24:16 vdr vdr[13315]: [13353] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: Successfully found following device: 0x1558ee0 (1) for receiving, priority=0
apr 01 23:24:16 vdr vdr[13315]: [13353] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 01 23:24:16 vdr vdr[13315]: [13353] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: Dummy receiver (0x15b1e10) activated
apr 01 23:24:16 vdr vdr[13315]: [13353] VNSI: activate live receiver: 1
apr 01 23:24:16 vdr vdr[13315]: [13353] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 01 23:24:23 vdr vdr[13315]: [13326] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):3071, rd:1573
apr 01 23:24:23 vdr vdr[13315]: [13341] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 CAM buff rd(-> CAM):0, wr:0
apr 01 23:24:23 vdr vdr[13315]: [13325] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):39012, wr:39415
apr 01 23:24:23 vdr vdr[13315]: [13342] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 CAM buff wr(CAM ->):0, rd:0
apr 01 23:24:25 vdr vdr[13315]: [13353] VNSI: Channel: no data 16
jasmin-j commented 7 years ago

I am pretty sure that your CAM doesn't decode the stream. To determine this, please add "-d 0x0800" to the ddci2 debug mask. Also remove one CAM, so it is easier to debug.

Another step could be to switch VDR back to 2.2.0. The Plugin should be able to compile with that version, too (if not, please create another issue). If the CAM can then decrypt, it might be a VDR problem due to the recent MTD changes.

Normally VDR should print the CAM system id's: [8606] CAM 1: AlphaCrypt, 01, 4A20, 4A20 [8606] CAM 1: system ids: 0D95 0648 1702 1722 1762 4A20 0500 0B00 0100 1833 1834 0D05 0D22 In your log I can't see this line.

When it works with VDR 2.2.0 and if you are able to program a little bit and you are a technician, you might be able to debug the issue in the VDR. Switch back to VDR 2.3.3. In file "ci.c" set DebugProtocol = true . Then you will get more logging from VDR. Then you can send this to Klaus S., the VDR Maintainer. Maybe he can help then.

BR, Jasmin

emilsvennesson commented 7 years ago

Luckily, I am running this in a VM and snapshots are making it a breeze to switch between versions. :-)

So I removed one CAM and added the -d 0x0800 debug flag:

-- Logs begin at Sun 2016-01-03 15:38:35 CET, end at Sun 2017-04-02 15:41:06 CEST. --
apr 02 15:39:32 vdr systemd[1]: Starting Video Disk Recorder...
apr 02 15:39:32 vdr vdr[484]: [484] VDR version 2.3.3 started
apr 02 15:39:32 vdr vdr[484]: [484] switched to user 'vdr'
apr 02 15:39:32 vdr vdr[484]: [484] codeset is 'UTF-8' - known
apr 02 15:39:32 vdr vdr[484]: [484] override character table is 'ISO-8859-15'
apr 02 15:39:34 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-ddci2.so.2.3.3
apr 02 15:39:34 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-devstatus.so.2.3.3
apr 02 15:39:34 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-restfulapi.so.2.3.3
apr 02 15:39:35 vdr vdr[484]: [484] restfulapi: Port has been set to 8002!
apr 02 15:39:35 vdr vdr[484]: [484] restfulapi: Ip has been set to 0.0.0.0!
apr 02 15:39:35 vdr vdr[484]: [484] restfulapi: can not add webapp 'webapp'! Path '/var/lib/vdr/restfulapi/webapp' does not exist!
apr 02 15:39:35 vdr vdr[484]: [484] restfulapi: trying to parse command line arguments
apr 02 15:39:35 vdr vdr[484]: [484] RESTful-API Settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
apr 02 15:39:35 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrmanager.so.2.3.3
apr 02 15:39:35 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrtva.so.2.3.3
apr 02 15:39:35 vdr vdr[484]: [484] loading plugin: /usr/lib/vdr/plugins/libvdr-vnsiserver.so.2.3.3
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/setup.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/sources.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/diseqc.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/scr.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/channels.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/timers.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/svdrphosts.conf
apr 02 15:39:35 vdr vdr[484]: [484] loading /var/lib/vdr/keymacros.conf
apr 02 15:39:36 vdr vdr[484]: [484] DVB API version is 0x050A (VDR was built with 0x050A)
apr 02 15:39:36 vdr vdr[484]: [484] frontend 0/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 15:39:36 vdr vdr[484]: [484] frontend 1/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 15:39:36 vdr vdr[484]: [484] found 2 DVB devices
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: ddci2 (1.0.2): External Digital Devices CI-Adapter
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: devstatus (0.4.1): Status of dvb devices
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: restfulapi (0.2.6.1): Offers a RESTful-API to retrieve data from VDR
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: vdrmanager (0.14): VDR-Manager plugin
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: vdrtva (0.3.6): Series Record plugin
apr 02 15:39:36 vdr vdr[484]: [484] initializing plugin: vnsiserver (1.5.2): VDR-Network-Streaming-Interface (VNSI) Server
apr 02 15:39:36 vdr vdr[484]: [484] setting primary device to 1
apr 02 15:39:36 vdr vdr[484]: [484] device 1 has no MPEG decoder
apr 02 15:39:36 vdr vdr[484]: [484] setting current skin to "lcars"
apr 02 15:39:36 vdr vdr[484]: [484] loading /var/lib/vdr/themes/lcars-default.theme
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: ddci2
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Inf: plugin version 1.0.2 initializing (compiled for VDR version 2.3.3)
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: Debug logging mask 0x1801
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: Buffer size 1500 packets
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: Sleep timer 100ms
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter3/ci0'
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter2/ci0'
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Inf: found 2 DD CI adapters
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Inf: Creating DdCiAdapter 0 (/dev/dvb/adapter2/ca0)
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter2/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) Reset slot 0
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Inf: Creating DdCiAdapter 1 (/dev/dvb/adapter3/ca0)
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter3/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 created
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) Reset slot 0
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 15:39:36 vdr vdr[484]: [484] DDCI-Inf: plugin started
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: devstatus
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: restfulapi
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Used settings: port: 8002, ip: 0.0.0.0, eimgs: , cimgs: , webapp: , headers: activated
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: The cached files will be loaded from /var/cache/vdr/plugins/restfulapi!
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: The config dir is /var/cache/vdr/plugins/restfulapi!
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: found 19 files in /*.
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: found 19 files in /*.
apr 02 15:39:36 vdr vdr[484]: [508] CAM 1: module present
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Webapp file types config file /var/lib/vdr/plugins/restfulapi/webapp_file_types.conf found.
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi finished.
apr 02 15:39:36 vdr vdr[484]: [484] restfulapi: using sync directory: /var/cache/vdr/plugins/restfulapi/sync
apr 02 15:39:36 vdr vdr[484]: [484] create server
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: vdrmanager
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: vdrtva
apr 02 15:39:36 vdr vdr[484]: [518] [vdrmanager] created non SSL server socket on port 6420
apr 02 15:39:36 vdr vdr[484]: [518] [vdrmanager] SSL key files /etc/vdr/plugins/vdrmanager/vdrmanager.pem and /etc/vdr/plugins/vdrmanager/vdrmanager.pem can't be read. SSL disabled.
apr 02 15:39:36 vdr vdr[484]: [484] vdrtva: series links file not found
apr 02 15:39:36 vdr vdr[484]: [484] starting plugin: vnsiserver
apr 02 15:39:36 vdr vdr[484]: [484] VNSI: Starting vnsi server at port=34890
apr 02 15:39:36 vdr vdr[484]: [484] VNSI: VNSI Server started
apr 02 15:39:36 vdr vdr[484]: [484] VNSI: Channel streaming timeout: 10 seconds
apr 02 15:39:36 vdr vdr[484]: [525] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 15:39:36 vdr vdr[484]: [525] VNSI: Client with ID 0 connected: 192.168.1.7:60104
apr 02 15:39:36 vdr vdr[484]: [525] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 15:39:36 vdr vdr[484]: [525] VNSI: Client with ID 1 connected: 192.168.1.171:49512
apr 02 15:39:36 vdr vdr[484]: [525] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 15:39:36 vdr vdr[484]: [525] VNSI: Client with ID 2 connected: 192.168.1.1:56441
apr 02 15:39:36 vdr vdr[484]: [530] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 15:39:36 vdr vdr[484]: [529] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 15:39:36 vdr vdr[484]: [528] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 15:39:37 vdr vdr[484]: [508] CAM 1: module ready
apr 02 15:39:38 vdr vdr[484]: [509] CAM 2: no module present
apr 02 15:39:39 vdr vdr[484]: [508] CAM 1: CryptoGuard CAM, 01, CAFE, BABE
apr 02 15:39:44 vdr vdr[484]: [484] switching to channel 4 (TV4 HD)
apr 02 15:39:44 vdr systemd[1]: Started Video Disk Recorder.
apr 02 15:39:44 vdr vdr[484]: [531] SVDRP listening on port 6419/tcp
apr 02 15:39:44 vdr vdr[484]: [484] ERROR: no OSD provider available - using dummy OSD!
apr 02 15:39:44 vdr vdr[484]: [484] vdrtva: Data capture started
apr 02 15:39:45 vdr vdr[484]: [526] VNSI: Requesting clients to reload channel list
apr 02 15:40:24 vdr vdr[484]: [525] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 15:40:24 vdr vdr[484]: [525] VNSI: Client with ID 3 connected: 192.168.1.5:62014
apr 02 15:40:24 vdr vdr[484]: [533] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 15:40:31 vdr vdr[484]: [525] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 15:40:31 vdr vdr[484]: [525] VNSI: Client with ID 4 connected: 192.168.1.5:62074
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: LiveStreamer::Close - close
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: close video input ...
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: allocated timeshift buffer with size: 500000000
apr 02 15:40:31 vdr vdr[484]: [534] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: Successfully found following device: 0x1238f00 (1) for receiving, priority=0
apr 02 15:40:31 vdr vdr[484]: [534] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 15:40:31 vdr vdr[484]: [534] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: Dummy receiver (0x7fd874003bc0) activated
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: activate live receiver: 1
apr 02 15:40:31 vdr vdr[484]: [534] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 15:40:31 vdr vdr[484]: [484] ERROR: no OSD provider available - using dummy OSD!
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: Successfully switched to channel 3 - TV3
apr 02 15:40:31 vdr vdr[484]: [534] VNSI: Started streaming of channel TV3 (timeout 10 seconds)
apr 02 15:40:31 vdr vdr[484]: [537] VNSI: Created stream for pid=3601 and type=7
apr 02 15:40:31 vdr vdr[484]: [537] VNSI: Created stream for pid=3604 and type=2
apr 02 15:40:31 vdr vdr[484]: [537] VNSI: Created stream for pid=3605 and type=2
apr 02 15:40:31 vdr vdr[484]: [537] VNSI: Created stream for pid=3602 and type=12
apr 02 15:40:32 vdr vdr[484]: [526] VNSI: Requesting clients to reload channel list
apr 02 15:40:33 vdr vdr[484]: [535] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 14 scrambled packets from CAM
apr 02 15:40:33 vdr vdr[484]: [535] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:33 vdr vdr[484]: [484] VNSI: re-tune to channel TV3
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: re-tuning...
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: close video input ...
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: activate live receiver: 0
apr 02 15:40:33 vdr vdr[484]: [537] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 15:40:33 vdr vdr[484]: [537] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: Dummy receiver (0x7fd874003bc0) deactivated
apr 02 15:40:33 vdr vdr[484]: [537] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: Successfully found following device: 0x1238f00 (1) for receiving, priority=0
apr 02 15:40:33 vdr vdr[484]: [537] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: Dummy receiver (0x1329c30) activated
apr 02 15:40:33 vdr vdr[484]: [537] VNSI: activate live receiver: 1
apr 02 15:40:33 vdr vdr[484]: [537] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 15:40:35 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 17 scrambled packets from CAM
apr 02 15:40:35 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:36 vdr vdr[484]: [514] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):4044, rd:2546
apr 02 15:40:36 vdr vdr[484]: [513] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):7157, wr:7374
apr 02 15:40:37 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 36 scrambled packets from CAM
apr 02 15:40:37 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:37 vdr vdr[484]: [526] VNSI: Requesting clients to reload channel list
apr 02 15:40:39 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 54 scrambled packets from CAM
apr 02 15:40:39 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:41 vdr vdr[484]: [537] VNSI: Channel: no data 16
apr 02 15:40:41 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 73 scrambled packets from CAM
apr 02 15:40:41 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:43 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 92 scrambled packets from CAM
apr 02 15:40:43 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:45 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 111 scrambled packets from CAM
apr 02 15:40:45 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:46 vdr vdr[484]: [514] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):4144, rd:2646
apr 02 15:40:46 vdr vdr[484]: [513] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):41811, wr:42236
apr 02 15:40:47 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 130 scrambled packets from CAM
apr 02 15:40:47 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:49 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 149 scrambled packets from CAM
apr 02 15:40:49 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:51 vdr vdr[484]: [537] VNSI: Channel: no data 16
apr 02 15:40:51 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 168 scrambled packets from CAM
apr 02 15:40:51 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:53 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 187 scrambled packets from CAM
apr 02 15:40:53 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:55 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 205 scrambled packets from CAM
apr 02 15:40:55 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:56 vdr vdr[484]: [514] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):4245, rd:2747
apr 02 15:40:56 vdr vdr[484]: [513] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):79147, wr:79430
apr 02 15:40:57 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 224 scrambled packets from CAM
apr 02 15:40:57 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:40:58 vdr vdr[484]: [526] VNSI: Requesting clients to reload channel list
apr 02 15:40:59 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 243 scrambled packets from CAM
apr 02 15:40:59 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:41:01 vdr vdr[484]: [537] VNSI: Channel: no data 16
apr 02 15:41:01 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 260 scrambled packets from CAM
apr 02 15:41:01 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:41:03 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 279 scrambled packets from CAM
apr 02 15:41:03 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:41:03 vdr vdr[484]: [526] VNSI: Requesting clients to reload channel list
apr 02 15:41:05 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 298 scrambled packets from CAM
apr 02 15:41:05 vdr vdr[484]: [538] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 clr 0 scrambling control bits
apr 02 15:41:06 vdr vdr[484]: [514] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):4347, rd:2849
apr 02 15:41:06 vdr vdr[484]: [513] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):117518, wr:117935

I then tried upgrading to ddci 1.0.2 on VDR 2.2 and it works! So it looks like this is an issue with the latest VDR version more than anything else. I am going to recompile it with DebugProtocol = true and see if I can get in touch with Klaus.

apr 02 16:00:29 vdr systemd[1]: Starting Video Disk Recorder...
apr 02 16:00:29 vdr vdr[2738]: [2738] VDR version 2.2.0 started
apr 02 16:00:29 vdr vdr[2738]: [2738] switched to user 'vdr'
apr 02 16:00:29 vdr vdr[2738]: [2738] codeset is 'UTF-8' - known
apr 02 16:00:29 vdr vdr[2738]: [2738] override character table is 'ISO-8859-15'
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-channellists.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-ddci2.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-devstatus.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-epgsearch.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-live.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-restfulapi.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Port has been set to 8002!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Ip has been set to 0.0.0.0!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: The EPG-Images will be loaded from /var/cache/vdr/epgimages!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: can not add webapp 'webapp'! Path '/var/lib/vdr/restfulapi/webapp' does not exist!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: trying to parse command line arguments
apr 02 16:00:29 vdr vdr[2738]: [2738] RESTful-API Settings: port: 8002, ip: 0.0.0.0, eimgs: /var/cache/vdr/epgimages, cimgs: , webapp: , headers: activated
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-streamdev-server.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrmanager.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-vdrtva.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading plugin: /usr/lib/vdr/plugins/libvdr-vnsiserver.so.2.2.0
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/setup.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/sources.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/diseqc.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/scr.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/channels.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/timers.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/svdrphosts.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/keymacros.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] DVB API version is 0x050A (VDR was built with 0x050A)
apr 02 16:00:29 vdr vdr[2738]: [2738] frontend 0/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 16:00:29 vdr vdr[2738]: [2738] frontend 1/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 16:00:29 vdr vdr[2738]: [2738] found 2 DVB devices
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: channellists (0.0.5): Manage your channellists
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: ddci2 (1.0.2): External Digital Devices CI-Adapter
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: devstatus (0.4.1): Status of dvb devices
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: epgsearch (1.0.1.beta5): search the EPG for repeats and more
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: live (0.3.0): Live Interactive VDR Environment
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: restfulapi (0.2.6.1): Offers a RESTful-API to retrieve data from VDR
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: streamdev-server (0.6.1-git): VDR Streaming Server
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: vdrmanager (0.14): VDR-Manager plugin
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: vdrtva (0.3.6): Series Record plugin
apr 02 16:00:29 vdr vdr[2738]: [2738] initializing plugin: vnsiserver (1.5.1): VDR-Network-Streaming-Interface (VNSI) Server
apr 02 16:00:29 vdr vdr[2738]: [2738] setting primary device to 1
apr 02 16:00:29 vdr vdr[2738]: [2738] device 1 has no MPEG decoder
apr 02 16:00:29 vdr vdr[2738]: [2738] SVDRP listening on port 6419
apr 02 16:00:29 vdr vdr[2738]: [2738] setting current skin to "lcars"
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/themes/lcars-default.theme
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: channellists
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: ddci2
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Inf: plugin version 1.0.2 initializing (compiled for VDR version 2.2.0)
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: Debug logging mask 0x1801
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: Buffer size 1500 packets
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: Sleep timer 100ms
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter3/ci0'
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter2/ci0'
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Inf: found 2 DD CI adapters
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Inf: Creating DdCiAdapter 0 (/dev/dvb/adapter2/ca0)
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter2/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) Reset slot 0
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Inf: Creating DdCiAdapter 1 (/dev/dvb/adapter3/ca0)
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter3/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 created
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) Reset slot 0
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 16:00:29 vdr vdr[2738]: [2738] DDCI-Inf: plugin started
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: devstatus
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: epgsearch
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/plugins/epgsearch/epgsearchmenu.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: live
apr 02 16:00:29 vdr vdr[2738]: [2738] LIVE: initial file cache has 82 entries and needs 377394 bytes of data!
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: restfulapi
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Used settings: port: 8002, ip: 0.0.0.0, eimgs: /var/cache/vdr/epgimages, cimgs: , webapp: , headers: activated
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: The cached files will be loaded from /var/cache/vdr/plugins/restfulapi!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: The config dir is /var/cache/vdr/plugins/restfulapi!
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: found 0 files in /var/cache/vdr/epgimages/*.
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: found 19 files in /*.
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Webapp file types config file /var/lib/vdr/plugins/restfulapi/webapp_file_types.conf found.
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for /var/cache/vdr/epgimages
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for /var/cache/vdr/epgimages finished.
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for epgimages or channellogos failed! (Check restfulapi-settings!)
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: Initializing inotify for /var/lib/vdr/plugins/restfulapi finished.
apr 02 16:00:29 vdr vdr[2738]: [2738] restfulapi: using sync directory: /var/cache/vdr/plugins/restfulapi/sync
apr 02 16:00:29 vdr vdr[2738]: [2738] create server
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: streamdev-server
apr 02 16:00:29 vdr vdr[2738]: [2738] loading /var/lib/vdr/plugins/streamdev-server/streamdevhosts.conf
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: vdrmanager
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: vdrtva
apr 02 16:00:29 vdr vdr[2738]: [2738] vdrtva: series links file not found
apr 02 16:00:29 vdr vdr[2738]: [2738] starting plugin: vnsiserver
apr 02 16:00:29 vdr vdr[2738]: [2738] VNSI: Starting vnsi server at port=34890
apr 02 16:00:29 vdr vdr[2738]: [2738] VNSI: VNSI Server started
apr 02 16:00:29 vdr vdr[2738]: [2738] VNSI: Channel streaming timeout: 10 seconds
apr 02 16:00:29 vdr vdr[2738]: [2756] [vdrmanager] created non SSL server socket on port 6420
apr 02 16:00:29 vdr vdr[2738]: [2756] [vdrmanager] SSL key files /etc/vdr/plugins/vdrmanager/vdrmanager.pem and /etc/vdr/plugins/vdrmanager/vdrmanager.pem can't be read. SSL disabled.
apr 02 16:00:29 vdr vdr[2738]: [2755] Streamdev: Listening (VTP) on port 2004
apr 02 16:00:29 vdr vdr[2738]: [2755] Streamdev: Listening (HTTP) on port 3000
apr 02 16:00:29 vdr vdr[2738]: [2751] [live] INFO: attempt to listen on ip = ''
apr 02 16:00:29 vdr vdr[2738]: [2751] [live] ERROR: Unable to load cert/key (/usr/share/vdr/plugins/live/live.pem//usr/share/vdr/plugins/live/live-key.pem): No such file or directory
apr 02 16:00:29 vdr vdr[2738]: [2761] VNSI: Requesting clients to reload channel list
apr 02 16:00:29 vdr vdr[2738]: [2757] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:00:29 vdr vdr[2738]: [2757] VNSI: Client with ID 0 connected: 192.168.1.171:54556
apr 02 16:00:29 vdr vdr[2738]: [2779] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:00:29 vdr vdr[2738]: [2748] CAM 1: module present
apr 02 16:00:29 vdr vdr[2738]: [2757] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:00:29 vdr vdr[2738]: [2757] VNSI: Client with ID 1 connected: 192.168.1.5:64552
apr 02 16:00:29 vdr vdr[2738]: [2780] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:00:29 vdr vdr[2738]: [2757] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:00:29 vdr vdr[2738]: [2757] VNSI: Client with ID 2 connected: 192.168.1.7:42664
apr 02 16:00:29 vdr vdr[2738]: [2781] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:00:30 vdr vdr[2738]: [2761] VNSI: Recordings state changed (3)
apr 02 16:00:30 vdr vdr[2738]: [2761] VNSI: Requesting clients to reload recordings list
apr 02 16:00:30 vdr vdr[2738]: [2748] CAM 1: module ready
apr 02 16:00:30 vdr vdr[2738]: [2757] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:00:30 vdr vdr[2738]: [2757] VNSI: Client with ID 3 connected: 192.168.1.1:48860
apr 02 16:00:30 vdr vdr[2738]: [2782] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:00:31 vdr vdr[2738]: [2749] CAM 2: no module present
apr 02 16:00:32 vdr vdr[2738]: [2748] CAM 1: CryptoGuard CAM, 01, CAFE, BABE
apr 02 16:00:34 vdr vdr[2738]: [2761] VNSI: Requesting clients to reload channel list
apr 02 16:00:38 vdr vdr[2738]: [2738] switching to channel 4 (TV4 HD)
apr 02 16:00:38 vdr systemd[1]: Started Video Disk Recorder.
apr 02 16:00:38 vdr vdr[2738]: [2738] ERROR: no OSD provider available - using dummy OSD!
apr 02 16:00:38 vdr vdr[2738]: [2738] vdrtva: Data capture started
apr 02 16:00:38 vdr vdr[2738]: [2738] ERROR: Channel locked (recording)!
apr 02 16:00:38 vdr vdr[2738]: [2750] EPGSearch: timer conflict check started
apr 02 16:00:38 vdr vdr[2738]: [2750] EPGSearch: timer conflict check finished
apr 02 16:00:39 vdr vdr[2738]: [2761] VNSI: Requesting clients to reload channel list
apr 02 16:00:39 vdr vdr[2738]: [2760] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):3358, rd:3360
apr 02 16:00:42 vdr vdr[2738]: [2757] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:00:42 vdr vdr[2738]: [2757] VNSI: Client with ID 4 connected: 192.168.1.5:64571
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: LiveStreamer::Close - close
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: close video input ...
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: allocated timeshift buffer with size: 500000000
apr 02 16:00:42 vdr vdr[2738]: [2783] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: Successfully found following device: 0x105bc00 (1) for receiving, priority=0
apr 02 16:00:42 vdr vdr[2738]: [2783] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:00:42 vdr vdr[2738]: [2783] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: Dummy receiver (0x7f6dd8019a80) activated
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: activate live receiver: 1, pmt change: 1
apr 02 16:00:42 vdr vdr[2738]: [2783] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: Successfully switched to channel 4 - TV4 HD
apr 02 16:00:42 vdr vdr[2738]: [2783] VNSI: Started streaming of channel TV4 HD (timeout 10 seconds)
apr 02 16:00:42 vdr vdr[2738]: [2786] VNSI: Created stream for pid=1581 and type=8
apr 02 16:00:42 vdr vdr[2738]: [2786] VNSI: Created stream for pid=1584 and type=1
apr 02 16:00:42 vdr vdr[2738]: [2786] VNSI: Created stream for pid=1582 and type=12
apr 02 16:00:42 vdr vdr[2738]: [2786] VNSI: Audio stream change, pid: 1584, channels: 2, samplerate: 48000
apr 02 16:00:43 vdr vdr[2738]: [2738] ERROR: no OSD provider available - using dummy OSD!
apr 02 16:00:43 vdr vdr[2738]: [2786] VNSI: Video stream change, pid: 1581, width: 1920, height: 1080, aspect: 1.777778
apr 02 16:00:44 vdr vdr[2738]: [2784] DDCI-Dbg: DdCiCamSlot for /dev/dvb/adapter2/ci0 got 1464 scrambled packets from CAM
jasmin-j commented 7 years ago

You stopped the log at [2784], but I guess the further DDCI-Dbg logging concerning scrambled packets did not increase. So the CAM was starting to de-scramble.

I am really interested on the outcome of this. So maybe you can put me in CC of the eMail to Klaus.

BR, Jasmin

emilsvennesson commented 7 years ago

@jasmin-j I am not quite sure how to contact Klaus. Do you know if he is on GitHub? I'd appreciate if you could direct him to this issue. :-) Here is a log from VDR 2.3.3 with DebugProtocol = true:

apr 02 16:39:07 vdr systemd[1]: Starting Video Disk Recorder...
apr 02 16:39:07 vdr vdr[13853]: [13853] VDR version 2.3.3 started
apr 02 16:39:07 vdr vdr[13853]: [13853] switched to user 'vdr'
apr 02 16:39:07 vdr vdr[13853]: [13853] codeset is 'UTF-8' - known
apr 02 16:39:07 vdr vdr[13853]: [13853] override character table is 'ISO-8859-15'
apr 02 16:39:07 vdr vdr[13853]: [13853] loading plugin: /usr/lib/vdr/plugins/libvdr-ddci2.so.2.3.3
apr 02 16:39:07 vdr vdr[13853]: [13853] loading plugin: /usr/lib/vdr/plugins/libvdr-vnsiserver.so.2.3.3
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/setup.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/sources.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/diseqc.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/scr.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/channels.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/timers.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/svdrphosts.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/keymacros.conf
apr 02 16:39:07 vdr vdr[13853]: [13853] DVB API version is 0x050A (VDR was built with 0x050A)
apr 02 16:39:07 vdr vdr[13853]: [13853] frontend 0/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 16:39:07 vdr vdr[13853]: [13853] frontend 1/0 provides DVB-C,DVB-T,DVB-T2,(null) with QPSK,QAM16,QAM32,QAM64,QAM128,QAM256 ("CXD2843 DVB-C/C2 DVB-T/T2")
apr 02 16:39:07 vdr vdr[13853]: [13853] found 2 DVB devices
apr 02 16:39:07 vdr vdr[13853]: [13853] initializing plugin: ddci2 (1.0.2): External Digital Devices CI-Adapter
apr 02 16:39:07 vdr vdr[13853]: [13853] initializing plugin: vnsiserver (1.5.2): VDR-Network-Streaming-Interface (VNSI) Server
apr 02 16:39:07 vdr vdr[13853]: [13853] setting primary device to 1
apr 02 16:39:07 vdr vdr[13853]: [13853] device 1 has no MPEG decoder
apr 02 16:39:07 vdr vdr[13853]: [13853] setting current skin to "lcars"
apr 02 16:39:07 vdr vdr[13853]: [13853] loading /var/lib/vdr/themes/lcars-default.theme
apr 02 16:39:07 vdr vdr[13853]: [13853] starting plugin: ddci2
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Inf: plugin version 1.0.2 initializing (compiled for VDR version 2.3.3)
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: Debug logging mask 0x1001
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: Buffer size 1500 packets
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: Sleep timer 100ms
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter3/ci0'
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: found DD CI adapter '/dev/dvb/adapter2/ci0'
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Inf: found 2 DD CI adapters
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Inf: Creating DdCiAdapter 0 (/dev/dvb/adapter2/ca0)
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter2/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) Reset slot 0
apr 02 16:39:07 vdr vdr[13853]: Slot 1: reset...ok.
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter2/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Inf: Creating DdCiAdapter 1 (/dev/dvb/adapter3/ca0)
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter3/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsRecvDeliver for /dev/dvb/adapter3/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter3/ci0 created
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) Reset slot 0
apr 02 16:39:07 vdr vdr[13853]: Slot 2: reset...ok.
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Dbg: DdCiAdapter(/dev/dvb/adapter3/ca0) created: DescrNum: 0, DescrType: 0, SlotNum: 1, , SlotType: 2
apr 02 16:39:07 vdr vdr[13853]: [13853] DDCI-Inf: plugin started
apr 02 16:39:07 vdr vdr[13853]: [13853] starting plugin: vnsiserver
apr 02 16:39:07 vdr vdr[13853]: [13853] VNSI: Starting vnsi server at port=34890
apr 02 16:39:07 vdr vdr[13853]: [13853] VNSI: VNSI Server started
apr 02 16:39:07 vdr vdr[13853]: [13853] VNSI: Channel streaming timeout: 10 seconds
apr 02 16:39:07 vdr vdr[13853]: [13864] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:39:07 vdr vdr[13853]: [13864] VNSI: Client with ID 0 connected: 192.168.1.171:34764
apr 02 16:39:07 vdr vdr[13853]: [13864] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:39:07 vdr vdr[13853]: [13864] VNSI: Client with ID 1 connected: 192.168.1.1:14616
apr 02 16:39:07 vdr vdr[13853]: [13874] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:39:07 vdr vdr[13853]: [13873] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:39:07 vdr vdr[13853]: Slot 1: module present
apr 02 16:39:07 vdr vdr[13853]: [13862] CAM 1: module present
apr 02 16:39:07 vdr vdr[13853]: [13864] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:39:07 vdr vdr[13853]: [13864] VNSI: Client with ID 2 connected: 192.168.1.7:60312
apr 02 16:39:07 vdr vdr[13853]: [13875] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:39:07 vdr vdr[13853]: [13864] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:39:07 vdr vdr[13853]: [13864] VNSI: Client with ID 3 connected: 192.168.1.5:53358
apr 02 16:39:07 vdr vdr[13853]: [13876] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:39:07 vdr vdr[13853]: [13865] VNSI: Requesting clients to reload recordings list
apr 02 16:39:08 vdr vdr[13853]: Slot 1: module ready
apr 02 16:39:08 vdr vdr[13853]: [13862] CAM 1: module ready
apr 02 16:39:08 vdr vdr[13853]: Slot 1: creating connection 0/1
apr 02 16:39:08 vdr vdr[13853]: Slot 1: create connection 0/1
apr 02 16:39:08 vdr vdr[13853]: Slot 1: connection created 0/1
apr 02 16:39:08 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:08 vdr vdr[13853]: Slot 1: open session 00010041
apr 02 16:39:08 vdr vdr[13853]: Slot 1: new Resource Manager (session id 1)
apr 02 16:39:08 vdr vdr[13853]: Slot 1: ==> Profile Enq (1)
apr 02 16:39:09 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:09 vdr vdr[13853]: Slot 2: no module present
apr 02 16:39:09 vdr vdr[13853]: [13863] CAM 2: no module present
apr 02 16:39:09 vdr vdr[13853]: Slot 1: <== Profile (1)
apr 02 16:39:09 vdr vdr[13853]: Slot 1: ==> Profile Change (1)
apr 02 16:39:09 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:09 vdr vdr[13853]: Slot 1: <== Profile Enquiry (1)
apr 02 16:39:09 vdr vdr[13853]: Slot 1: ==> Profile (1)
apr 02 16:39:10 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:10 vdr vdr[13853]: Slot 1: open session 00020041
apr 02 16:39:10 vdr vdr[13853]: Slot 1: new Application Information (session id 2)
apr 02 16:39:10 vdr vdr[13853]: Slot 1: ==> Application Info Enq (2)
apr 02 16:39:10 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:10 vdr vdr[13853]: Slot 1: <== Application Info (2)
apr 02 16:39:10 vdr vdr[13853]: [13862] CAM 1: CryptoGuard CAM, 01, CAFE, BABE
apr 02 16:39:11 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:11 vdr vdr[13853]: Slot 1: open session 00400041
apr 02 16:39:11 vdr vdr[13853]: Slot 1: new MMI (session id 3)
apr 02 16:39:11 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:11 vdr vdr[13853]: Slot 1: <== Display Control (3)
apr 02 16:39:11 vdr vdr[13853]: Slot 1: ==> Display Reply (3)
apr 02 16:39:11 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Menu Last (3)
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) 'CryptoGuard CAM'
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) ''
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) ''
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) 'Access to services can be '
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) 'limited because your TV set is'
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Text Last (3) 'not CI+ compatible.'
apr 02 16:39:12 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:12 vdr vdr[13853]: Slot 1: open session 00030041
apr 02 16:39:12 vdr vdr[13853]: Slot 1: new Conditional Access Support (session id 4)
apr 02 16:39:12 vdr vdr[13853]: Slot 1: ==> Ca Info Enq (4)
apr 02 16:39:12 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:12 vdr vdr[13853]: Slot 1: <== Ca Info (4) 0B00
apr 02 16:39:13 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 3
apr 02 16:39:15 vdr vdr[13853]: [13853] switching to channel 1 (SVT1 HD)
apr 02 16:39:15 vdr systemd[1]: Started Video Disk Recorder.
apr 02 16:39:15 vdr vdr[13853]: [13877] SVDRP listening on port 6419/tcp
apr 02 16:39:15 vdr vdr[13853]: [13853] ERROR: no OSD provider available - using dummy OSD!
apr 02 16:39:16 vdr vdr[13853]: [13865] VNSI: Requesting clients to reload channel list
apr 02 16:39:17 vdr vdr[13853]: Slot 1: receive data 0/1
apr 02 16:39:17 vdr vdr[13853]: Slot 1: close session 3
apr 02 16:40:00 vdr vdr[13853]: [13864] loading /var/lib/vdr/plugins/vnsiserver/allowed_hosts.conf
apr 02 16:40:00 vdr vdr[13853]: [13864] VNSI: Client with ID 4 connected: 192.168.1.5:53432
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: Welcome client 'XBMC Media Center' with protocol version '10'
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: LiveStreamer::Close - close
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: close video input ...
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: allocated timeshift buffer with size: 500000000
apr 02 16:40:00 vdr vdr[13853]: [13880] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: Successfully found following device: 0xbe3760 (1) for receiving, priority=0
apr 02 16:40:00 vdr vdr[13853]: [13880] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:40:00 vdr vdr[13853]: [13880] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:40:00 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 4
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: Dummy receiver (0x7fe08400b700) activated
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: activate live receiver: 1
apr 02 16:40:00 vdr vdr[13853]: [13880] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:40:00 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 1
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: Successfully switched to channel 4 - TV4 HD
apr 02 16:40:00 vdr vdr[13853]: [13880] VNSI: Started streaming of channel TV4 HD (timeout 10 seconds)
apr 02 16:40:01 vdr vdr[13853]: [13853] ERROR: no OSD provider available - using dummy OSD!
apr 02 16:40:01 vdr vdr[13853]: [13883] VNSI: Created stream for pid=1581 and type=8
apr 02 16:40:01 vdr vdr[13853]: [13883] VNSI: Created stream for pid=1584 and type=1
apr 02 16:40:01 vdr vdr[13853]: [13883] VNSI: Created stream for pid=1582 and type=12
apr 02 16:40:01 vdr vdr[13853]: [13865] VNSI: Requesting clients to reload channel list
apr 02 16:40:02 vdr vdr[13853]: [13853] VNSI: re-tune to channel TV4 HD
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: re-tuning...
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: close video input ...
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: activate live receiver: 0
apr 02 16:40:02 vdr vdr[13853]: [13883] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:40:02 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 4
apr 02 16:40:02 vdr vdr[13853]: [13883] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:40:02 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 4
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: Dummy receiver (0x7fe08400b700) deactivated
apr 02 16:40:02 vdr vdr[13853]: [13883] DDCI-Dbg (virtual void DdCiCamSlot::StopDecrypting())
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: Successfully found following device: 0xbe3760 (1) for receiving, priority=0
apr 02 16:40:02 vdr vdr[13853]: [13883] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: Dummy receiver (0x7fe08c003b80) activated
apr 02 16:40:02 vdr vdr[13853]: [13883] VNSI: activate live receiver: 1
apr 02 16:40:02 vdr vdr[13853]: [13883] DDCI-Dbg (virtual void DdCiCamSlot::StartDecrypting())
apr 02 16:40:02 vdr vdr[13853]: Slot 1: ==> Ca Pmt (4) 3 1
apr 02 16:40:07 vdr vdr[13853]: [13871] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):7433, rd:5936
apr 02 16:40:07 vdr vdr[13853]: [13870] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):26049, wr:26465
apr 02 16:40:10 vdr vdr[13853]: [13883] VNSI: Channel: no data 16
apr 02 16:40:17 vdr vdr[13853]: [13871] DDCI-Dbg: DdCiTsRecv for /dev/dvb/adapter2/ci0 CAM buff wr(CAM ->):7534, rd:6038
apr 02 16:40:17 vdr vdr[13853]: [13870] DDCI-Dbg: DdCiTsSend for /dev/dvb/adapter2/ci0 CAM buff rd(-> CAM):70331, wr:70682
apr 02 16:40:20 vdr vdr[13853]: [13883] VNSI: Channel: no data 16
emilsvennesson commented 7 years ago

I didn't notice before, but it says that it successfully switched to the channel. I am not getting any picture though, and VNSI says that there's no data.

jasmin-j commented 7 years ago

But VNSI says: -> VNSI: Channel: no data 16 and you doesn't see a picture, so it is not decrypting. You should activate the -d 0x0800 debug flag again. Then we will see if there will be decrypted or not. If the number in the log "... got XXXX scrambled packets from CAM" increases, it is not decrypting.

jasmin-j commented 7 years ago

Any news on this subject?

emilsvennesson commented 7 years ago

Everything works great on VDR 2.3.7 and ddci2 1.0.5.

Big thanks to you and Klaus for fixing this!