search

manio / vdr-plugin-dvbapi

VDR dvbapi plugin for use with OSCam
http://www.streamboard.tv/wbb2/thread.php?threadid=40060
GNU General Public License v2.0
57 stars 25 forks source link

No decoding after switching from encoded to FTA and back [vdr-2.1.6, latest dvbapi, oscam 9095] #63

Closed jeanpijon closed 10 years ago

jeanpijon commented 10 years ago

Hi Mariusz, I am not sure, if this is a problem in dvabapi, vdr or oscam, but I have to start somewhere.

I have a problem with combination of vdr 2.1.6 latest dvbapi plugin from git and oscam 9095 (I also tried latest trunk). Trying to decode 0624 ECM (Skylink) with ICE card. Used to work great with old vdr and oscam.

How to reproduce this: start system, vdr kicks in, oscam initializes, I can see EMM going through, everything is ok - log while switching:

2014/07/10 02:28:17  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #4 CAID 0624 PROVID 000000 ECMPID 0F01 ANY CHID VPID 00A2
2014/07/10 02:28:18  226B180 c vdr (0624&000000/0000/1F43/55:2E3BE4FEAE8AACE49ED2F660B19E7FBE): found (118 ms) by skylink - CT1
2014/07/10 02:28:20  226B180 c vdr (0624&000000/0000/1F43/55:AF91733E5A42BAF014A6B90D74F8C529): found (119 ms) by skylink - CT1
2014/07/10 02:28:25  226B180 c [DVBAPI] Receiver sends PMT command 3 for channel 3352
2014/07/10 02:28:25  226B180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0001 camask 0002 index 0000
2014/07/10 02:28:25  226B180 c [ADD PID 0] CAID: 0D96 ECM_PID: 0F0E PROVID: 000000
2014/07/10 02:28:25  226B180 c [ADD PID 1] CAID: 0624 ECM_PID: 0F0F PROVID: 000000
2014/07/10 02:28:25  226B180 c [ADD PID 2] CAID: 0666 ECM_PID: 005B PROVID: 000000
2014/07/10 02:28:25  226B180 c Found 3 ECMpids and 2 STREAMpids in PMT
2014/07/10 02:28:25  226B180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0001 camask 0002 index 0000
2014/07/10 02:28:25  226B180 c New program number: 3352 (Nova) [pmt_list_management 3]
2014/07/10 02:28:25  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/07/10 02:28:26  226B180 c vdr (0624&000000/0000/3352/59:DD6377C78CBDE3FB1EA3819BEBEC8FDB): found (120 ms) by skylink - Nova
2014/07/10 02:28:32  226B180 c vdr (0624&000000/0000/3352/59:B81A9C14D08645CDC0C6248AA48A14E2): found (121 ms) by skylink - Nova
2014/07/10 02:28:32  226B180 c [DVBAPI] Receiver sends PMT command 3 for channel 1F42
2014/07/10 02:28:32  226B180 c [DVBAPI] Receiver wants to demux srvid 1F42 on adapter 0001 camask 0002 index 0000
2014/07/10 02:28:32  226B180 c [ADD PID 0] CAID: 0D96 ECM_PID: 0F06 PROVID: 000000
2014/07/10 02:28:32  226B180 c [ADD PID 1] CAID: 0624 ECM_PID: 0F07 PROVID: 000000
2014/07/10 02:28:32  226B180 c [ADD PID 2] CAID: 0666 ECM_PID: 0127 PROVID: 000000
2014/07/10 02:28:32  226B180 c Found 3 ECMpids and 2 STREAMpids in PMT
2014/07/10 02:28:32  226B180 c [DVBAPI] Receiver wants to demux srvid 1F42 on adapter 0001 camask 0002 index 0000
2014/07/10 02:28:32  226B180 c New program number: 1F42 (Prima) [pmt_list_management 3]
2014/07/10 02:28:32  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F07 ANY CHID VPID 00A1
2014/07/10 02:28:33  226B180 c vdr (0624&000000/0000/1F42/55:E305F4AD176CCB1B6D87CC246B967544): found (118 ms) by skylink - Prima
2014/07/10 02:28:33  2253470 r skylink [irdeto] vdr emmtype=global, len=12, idx=13, cnt=1: written (45 ms)
2014/07/10 02:28:33  2253470 r skylink [irdeto] vdr emmtype=global, len=12, idx=13, cnt=2: written (44 ms)
2014/07/10 02:28:33  2253470 r skylink [irdeto] vdr emmtype=global, len=13, idx=14, cnt=1: written (47 ms)
2014/07/10 02:28:33  2253470 r skylink [irdeto] vdr emmtype=global, len=37, idx=15, cnt=1: written (69 ms)

then switch to FTA channel and back to encrypted. And oscam will start telling this:

2014/07/10 02:29:35  226B180 c [DVBAPI] Receiver sends PMT command 3 for channel 3352
2014/07/10 02:29:35  226B180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0001 camask 0002 index 0000
2014/07/10 02:29:35  226B180 c [ADD PID 0] CAID: 0D96 ECM_PID: 0F0E PROVID: 000000
2014/07/10 02:29:35  226B180 c [ADD PID 1] CAID: 0624 ECM_PID: 0F0F PROVID: 000000
2014/07/10 02:29:35  226B180 c [ADD PID 2] CAID: 0666 ECM_PID: 005B PROVID: 000000
2014/07/10 02:29:35  226B180 c Found 3 ECMpids and 2 STREAMpids in PMT
2014/07/10 02:29:35  226B180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0001 camask 0002 index 0000
2014/07/10 02:29:35  226B180 c New program number: 3352 (Nova) [pmt_list_management 3]
2014/07/10 02:29:35  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/07/10 02:29:38  226B180 c [DVBAPI] Demuxer #0 (re)starting decodingrequests on all 3 ecmpids!
2014/07/10 02:29:39  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/07/10 02:29:42  226B180 c [DVBAPI] Demuxer #0 (re)starting decodingrequests on all 3 ecmpids!
2014/07/10 02:29:42  226B180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81

and what is worse, restart of VDR and oscam doesn't help. only restart of the whole SYSTEM.

If I restart just vdr and oscam, oscam shows just initialization and nothing more:

-------------------------------------------------------------------------------
>> OSCam <<  cardserver started at Thu Jul 10 02:42:23 2014
-------------------------------------------------------------------------------
2014/07/10 02:42:23        0 s >> OSCam <<  cardserver started, version 1.20-unstable_svn, build r9095 (x86_64-linux-gnu)
2014/07/10 02:42:23        0 s creating pidfile /tmp/.oscam/oscam.pid with pid 3902
2014/07/10 02:42:23        0 s userdb reloaded: 1 accounts loaded, 0 expired, 0 disabled
2014/07/10 02:42:23        0 s signal handling initialized
2014/07/10 02:42:23        0 s 139 service-id's loaded in 0ms
2014/07/10 02:42:23        0 s Binary without Nagra module - no EMM processing for Nagra possible!
2014/07/10 02:42:23        0 s Binary without Conax module - no EMM processing for Conax possible!
2014/07/10 02:42:23        0 s Binary without Seca module - no EMM processing for Seca possible!
2014/07/10 02:42:23        0 s Binary without Viaccess module - no EMM processing for Viaccess possible!
2014/07/10 02:42:23        0 s Binary without NDS Videoguard module - no EMM processing for NDS Videoguard possible!
2014/07/10 02:42:23        0 s Binary without DRE Crypt module - no EMM processing for DRE Crypt possible!
2014/07/10 02:42:23        0 s Binary without TONGFANG module - no EMM processing for TONGFANG possible!
2014/07/10 02:42:23        0 s Binary without Bulcrypt module - no EMM processing for Bulcrypt possible!
2014/07/10 02:42:23        0 s Binary without Griffin module - no EMM processing for Griffin possible!
2014/07/10 02:42:23        0 s Binary without DGCrypt module - no EMM processing for DGCrypt possible!
2014/07/10 02:42:23        0 s skylink [mouse] creating thread for device /dev/ttyS0
2014/07/10 02:42:23        0 s loadbalancer: can't read from file /tmp/.oscam/stat
2014/07/10 02:42:23        0 s waiting for local card init
2014/07/10 02:42:23 C00008C0 h webif: decompressed 54698 bytes back into 156344 bytes
2014/07/10 02:42:23 C00008C0 h HTTP Server running. ip=0.0.0.0 port=10001
2014/07/10 02:42:23   A3D0D0 r skylink [mouse] Reader initialized (device=/dev/ttyS0, detect=none, mhz=600, cardmhz=357)
2014/07/10 02:42:24   A3D0D0 r skylink [mouse] card detected
2014/07/10 02:42:25   A3D0D0 r skylink [mouse] ATR: 3B 78 12 00 00 54 C4 03 00 8F F1 90 00
2014/07/10 02:42:25   A3D0D0 r skylink [mouse] Init card protocol T0, FI=1, F=372, D=2, N=0
2014/07/10 02:42:25   A3D0D0 r skylink [mouse] Calculated work ETU is 62.00 us reader mhz = 600
2014/07/10 02:42:25   A3D0D0 r skylink [mouse] ATR Fsmax is 5 MHz, clocking card to wanted user cardspeed off 6.00 MHz (specified in reader->mhz)
2014/07/10 02:42:26   A3D0D0 r skylink [mouse] Hist. Bytes: T<C4>^C
2014/07/10 02:42:26   A3D0D0 r skylink [mouse] detect irdeto card
2014/07/10 02:42:26   A3D0D0 r skylink [mouse] caid: 0624, acs: 0.06, country code: CZE
2014/07/10 02:42:26   A3D0D0 r skylink [mouse] providers: 4, ascii serial: ##########, hex serial: ######, hex base: ##
2014/07/10 02:42:27   A3D0D0 r skylink [mouse] WARNING: For Irdeto cards you will have to set 'cardmhz = 600' in oscam.server
2014/07/10 02:42:27   A3D0D0 r skylink [mouse] active providers: 4 (4e5bff,ffffff,ffffff,ffffff)
2014/07/10 02:42:27   A3D0D0 r skylink [mouse] found card system irdeto
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] THIS WAS A SUCCESFULL START ATTEMPT No  1 out of max alloted of 1
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 1389, date: 2011/12/31 - 2012/01/19
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 138A, date: 2011/12/31 - 2012/01/19
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 138B, date: 2011/12/31 - 2012/01/19
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 1771, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 03E9, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 03EB, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 03EA, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 7FFD, date: 2014/07/09 - 2014/07/19
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 03EC, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: FFD8, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 03ED, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 7FFE, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: 7FFC, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: FFB0, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] chid: FFE0, date: 2014/07/09 - 2014/08/08
2014/07/10 02:42:27   A3D0D0 r skylink [irdeto] ready for requests
2014/07/10 02:42:28        0 s init for all local cards done
2014/07/10 02:42:28        0 s anti cascading disabled
2014/07/10 02:42:28   A3EE00 c plain dvbapi-client granted (vdr, au=auto (1 reader))
2014/07/10 02:42:28   A3EE00 c [DVBAPI] Detected /dev/dvb/adapter0/demux0 Api: 0, userconfig boxtype: 11

And VDR simply refuse to talk to oscam I guess.

Jul 10 02:42:23 htpc vdr: [3957] CAM 1: module present
Jul 10 02:42:24 htpc vdr: [3958] CAM 2: module ready
Jul 10 02:42:24 htpc vdr: [3957] CAM 1: module ready
Jul 10 02:42:24 htpc vdr: [3958] CAM 2: system ids: FFFF
Jul 10 02:42:24 htpc vdr: [3957] CAM 1: system ids: FFFF
Jul 10 02:42:24 htpc vdr: [3959] CAM 3: module ready
Jul 10 02:42:24 htpc vdr: [3959] CAM 3: system ids: FFFF
Jul 10 02:42:25 htpc vdr: [3958] CAM 2: replies to QUERY - multi channel decryption possible
Jul 10 02:42:25 htpc vdr: [3957] CAM 1: replies to QUERY - multi channel decryption possible
Jul 10 02:42:25 htpc vdr: [3959] CAM 3: replies to QUERY - multi channel decryption possible
Jul 10 02:42:25 htpc vdr: [3907] switching to channel 1
Jul 10 02:42:26 htpc vdr: [3907] CAM 2: assigned to device 2
Jul 10 02:42:26 htpc vdr: [3973] receiver on device 2 thread started (pid=3907, tid=3973, prio=high)
Jul 10 02:42:26 htpc vdr: [3907] OSD size changed to 1920x1080 @ 1
Jul 10 02:42:26 htpc vdr: [3974] TS buffer on device 2 thread started (pid=3907, tid=3974, prio=high)
Jul 10 02:42:26 htpc vdr: [3907] dbus2vdr: raise SIGSTOP for Upstart
Jul 10 02:42:26 htpc vdr: [3955] EPGSearch: timer conflict check started
Jul 10 02:42:26 htpc vdr: [3955] EPGSearch: timer conflict check finished
Jul 10 02:42:28 htpc vdr: [3954] loading /var/lib/vdr/plugins/xvdr/allowed_hosts.conf
Jul 10 02:42:28 htpc vdr: [3954] XVDR: Client 127.0.0.1:4256 with ID 0 connected.
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Welcome client 'XVDR Client' with protocol version '5'
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Preferred language: cze,ces / type: 0
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Channellist filter:
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Free To Air channels: Yes
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Only native language: No
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Enabled CaIDs:
Jul 10 02:42:28 htpc vdr: [3981] XVDR: 0624
Jul 10 02:42:28 htpc vdr: [3981] XVDR: Setting channel update method: 3
Jul 10 02:42:28 htpc vdr: [3981] XVDR-Error: Unable to connect to wirbelscan plugin !
Jul 10 02:42:30 htpc vdr: [3973] detaching receiver - won't decrypt channel S23.5E-1-1106-8003 with CAM 2
Jul 10 02:42:30 htpc vdr: [3973] CAM 2: unassigned

Thanks for any possible direction you can point me, I am seriously lost now. Regards Jean

manio commented 10 years ago

Hello Jean, After reading your logs I cannot exactly tell you the cause of the problem. When you have problem for the first time, in fact my plugin passes to oscam the same complete PMT data for Nova. If you need to restart the whole system then it smells to me like a driver problem... but I am not sure without more detailed debug logs.

jeanpijon commented 10 years ago

Hi Mariusz, I will supply you another debug logs, just tell me which one you want. Regards Jan

2014-07-10 9:34 GMT+02:00, Mariusz Białończyk notifications@github.com:

Hello Jean, After reading your logs I cannot exactly tell you the cause of the problem. When you have problem for the first time, in fact my plugin passes to oscam the same complete PMT data for Nova. If you need to restart the whole system then it smells to me like a driver problem... but I am not sure without more detailed debug logs.

Reply to this email directly or view it on GitHub: https://github.com/manio/vdr-plugin-dvbapi/issues/63#issuecomment-48573612

manio commented 10 years ago

Lets start with dvbapi plugin loglevel=3 and oscam with level=128

jeanpijon commented 10 years ago

Ok, here we go. Log after switch from FTA channel.

vdr.log

Jul 15 22:31:50 htpc vdr: [24124] XVDR: Started streaming of channel CT sport (timeout 10 seconds, priority 50)
Jul 15 22:31:50 htpc vdr: [24382] cLiveStreamer stream processor thread started (pid=23823, tid=24382, prio=high)
Jul 15 22:31:50 htpc vdr: [24382] XVDR: streamer thread started.
Jul 15 22:31:50 htpc vdr: [24381] XVDR: LiveQueue started
Jul 15 22:31:50 htpc vdr: [24353] TS buffer on device 2 thread ended (pid=23823, tid=24353)
Jul 15 22:31:50 htpc vdr: [24352] buffer stats: 49444 (0%) used
Jul 15 22:31:50 htpc vdr: [24352] receiver on device 2 thread ended (pid=23823, tid=24352)
Jul 15 22:31:50 htpc vdr: [24382] CAM 2: assigned to device 2
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Found available device 2
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Channel information found in cache
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Creating demuxers
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Stream: TELETEXT PID: 32 TXT (parsed: yes)
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Stream: MPEG2AUDIO PID: 102 48000 Hz, 2 channels, Lang: cze (parsed: yes)
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Stream: MPEG2AUDIO PID: 105 48000 Hz, 1 channels, Lang: cze (parsed: yes)
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Stream: MPEG2VIDEO PID: 166 720x576 DAR: 1,78 FPS: 25,000 (parsed: yes)
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Successfully switched to channel 5 - CT sport
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: 1.0 CA_PMT decoding len=34 lm=4 prg=8007 len=1f
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: ci_cmd(G)=01
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: pid=2,00a6 len=0 (0x0)
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: pid=4,0066 len=0 (0x0)
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: pid=4,0069 len=0 (0x0)
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: 1.0 got CA pmt ciCmd=1 caLm=4
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: 1.0 set CAM decrypt (SID 8007, caLm 4, HasCaDescriptors 1)
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: send: channelSid=0x1f47 (8007)
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: created socket with socket_fd=37
Jul 15 22:31:50 htpc vdr: [24382] DVBAPI: socket_fd=37 len=62 wrote=62
Jul 15 22:31:50 htpc vdr: [24382] XVDR: Starting PAT scanner
Jul 15 22:31:50 htpc vdr: [24382] XVDR: done switching.
Jul 15 22:31:50 htpc vdr: [24386] receiver on device 2 thread started (pid=23823, tid=24386, prio=high)
Jul 15 22:31:50 htpc vdr: [24387] TS buffer on device 2 thread started (pid=23823, tid=24387, prio=high)
Jul 15 22:31:51 htpc vdr: [23823] switching to channel 1
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 CA_PMT decoding len=43 lm=4 prg=8003 len=25
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(G)=03
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=2,00a2 len=1 (0x1)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(S)=03
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,0058 len=1 (0x1)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(S)=03
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,005b len=1 (0x1)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(S)=03
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,0062 len=1 (0x1)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(S)=03
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 got CA pmt ciCmd=3 caLm=4
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 answer to query
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 no action taken
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 CA_PMT decoding len=3f lm=4 prg=8003 len=25
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: ci_cmd(G)=01
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=2,00a2 len=0 (0x0)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,0058 len=0 (0x0)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,005b len=0 (0x0)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: pid=4,0062 len=0 (0x0)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 got CA pmt ciCmd=1 caLm=4
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: 1.0 set CAM decrypt (SID 8003, caLm 4, HasCaDescriptors 1)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: send: channelSid=0x1f47 (8007)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: socket_fd=37 len=62 wrote=62
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: send: channelSid=0x1f43 (8003)
Jul 15 22:31:51 htpc vdr: [23823] DVBAPI: socket_fd=37 len=73 wrote=73
Jul 15 22:31:55 htpc vdr: [24386] detaching receiver - won't decrypt channel -0-0-0 with CAM 2
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 CA_PMT decoding len=25 lm=5 prg=8007 len=1f
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: ci_cmd(G)=01
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 got CA pmt ciCmd=1 caLm=5
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 set CAM decrypt (SID 8007, caLm 5, HasCaDescriptors 1)
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: send: channelSid=0x1f43 (8003)
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: socket_fd=37 len=73 wrote=73
Jul 15 22:31:55 htpc vdr: [24386] detaching receiver - won't decrypt channel S23.5E-1-1106-8003 with CAM 2
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 CA_PMT decoding len=2b lm=5 prg=8003 len=25
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: ci_cmd(G)=01
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 got CA pmt ciCmd=1 caLm=5
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 set CAM decrypt (SID 8003, caLm 5, HasCaDescriptors 1)
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: StopAllFilters
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 CA_PMT decoding len=6 lm=3 prg=0 len=0
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 got CA pmt ciCmd=-1 caLm=3
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:55 htpc vdr: [24386] DVBAPI: 1.0 stop decrypt
Jul 15 22:31:55 htpc vdr: [24386] CAM 2: unassigned
Jul 15 22:31:55 htpc vdr: [24382] CAM 2: assigned to device 2
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Found available device 2
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Channel information found in cache
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Creating demuxers
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Stream: TELETEXT PID: 32 TXT (parsed: yes)
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Stream: MPEG2AUDIO PID: 102 48000 Hz, 2 channels, Lang: cze (parsed: yes)
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Stream: MPEG2AUDIO PID: 105 48000 Hz, 1 channels, Lang: cze (parsed: yes)
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Stream: MPEG2VIDEO PID: 166 720x576 DAR: 1,78 FPS: 25,000 (parsed: yes)
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Successfully switched to channel 5 - CT sport
Jul 15 22:31:55 htpc vdr: [24387] TS buffer on device 2 thread ended (pid=23823, tid=24387)
Jul 15 22:31:55 htpc vdr: [24386] buffer stats: 113928 (2%) used
Jul 15 22:31:55 htpc vdr: [24386] receiver on device 2 thread ended (pid=23823, tid=24386)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: 1.0 CA_PMT decoding len=34 lm=4 prg=8007 len=1f
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: ci_cmd(G)=01
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: pid=2,00a6 len=0 (0x0)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: pid=4,0066 len=0 (0x0)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: pid=4,0069 len=0 (0x0)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: 1.0 got CA pmt ciCmd=1 caLm=4
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: 1.0 answer to query suppressed
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: 1.0 set CAM decrypt (SID 8007, caLm 4, HasCaDescriptors 1)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: send: channelSid=0x1f47 (8007)
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: created socket with socket_fd=42
Jul 15 22:31:55 htpc vdr: [24382] DVBAPI: socket_fd=42 len=62 wrote=62
Jul 15 22:31:55 htpc vdr: [24382] XVDR: Starting PAT scanner
Jul 15 22:31:55 htpc vdr: [24382] XVDR: done switching.
Jul 15 22:31:55 htpc vdr: [24397] receiver on device 2 thread started (pid=23823, tid=24397, prio=high)
Jul 15 22:31:55 htpc vdr: [24398] TS buffer on device 2 thread started (pid=23823, tid=24398, prio=high)
Jul 15 22:31:55 htpc vdr: [23823] switching to channel 1
Jul 15 22:31:55 htpc vdr: [23823] info: Kanál není dostupný!
Jul 15 22:31:59 htpc vdr: [24397] detaching receiver - won't decrypt channel -0-0-0 with CAM 2
and so on...
oscam.log
2014/07/15 22:31:29  188ED90 c Got sigpipe signal -> captured
2014/07/15 22:31:50  188ED90 c new socket connection fd: 7
2014/07/15 22:31:50  188ED90 c New PMT info from socket (total size: 62)
2014/07/15 22:31:50  188ED90    9F 80 32 82 00 38 03 1F 47 00 00 23 01 82 02 00
2014/07/15 22:31:50  188ED90    01 09 04 0D 0F E6 51 09 04 0D 03 E6 11 09 04 0D
2014/07/15 22:31:50  188ED90    96 EF 04 09 04 06 24 EF 05 09 04 06 66 E1 22 02
2014/07/15 22:31:50  188ED90    00 A6 00 00 04 00 66 00 00 04 00 69 00 00
2014/07/15 22:31:50  188ED90 c capmt:
2014/07/15 22:31:50  188ED90    03 1F 47 00 00 23 01 82 02 00 01 09 04 0D 0F E6
2014/07/15 22:31:50  188ED90    51 09 04 0D 03 E6 11 09 04 0D 96 EF 04 09 04 06
2014/07/15 22:31:50  188ED90    24 EF 05 09 04 06 66 E1 22 02 00 A6 00 00 04 00
2014/07/15 22:31:50  188ED90    66 00 00 04 00 69 00 00
2014/07/15 22:31:50  188ED90 c [DVBAPI] Receiver sends PMT command 3 for channel 1F47
2014/07/15 22:31:50  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F47 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:50  188ED90 c [pmt] type: 82 length: 2
2014/07/15 22:31:50  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:50  188ED90 c [ADD PID 0] CAID: 0D0F ECM_PID: 0651 PROVID: 000000
2014/07/15 22:31:50  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:50  188ED90 c [ADD PID 1] CAID: 0D03 ECM_PID: 0611 PROVID: 000000
2014/07/15 22:31:50  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:50  188ED90 c [ADD PID 2] CAID: 0D96 ECM_PID: 0F04 PROVID: 000000
2014/07/15 22:31:50  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:50  188ED90 c [ADD PID 3] CAID: 0624 ECM_PID: 0F05 PROVID: 000000
2014/07/15 22:31:50  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:50  188ED90 c [ADD PID 4] CAID: 0666 ECM_PID: 0122 PROVID: 000000
2014/07/15 22:31:50  188ED90 c [pmt] stream_type: 02 pid: 00a6 length: 0
2014/07/15 22:31:50  188ED90 c [pmt] stream_type: 04 pid: 0066 length: 0
2014/07/15 22:31:50  188ED90 c [pmt] stream_type: 04 pid: 0069 length: 0
2014/07/15 22:31:50  188ED90 c Found 5 ECMpids and 3 STREAMpids in PMT
2014/07/15 22:31:50  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F47 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:50  188ED90 c New program number: 1F47 (0D0F:1F47 unknown) [pmt_list_management 3]
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 demux_index:  0 ca_mask: 02 program_info_length:  35 ca_pmt_list_management 03
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 try to start new filter for caid: 0001, provid: 000001, pid: 0001
2014/07/15 22:31:50  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 14
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 Filter #1 started succesfully (caid 0001 provid 000001 pid 0001)
2014/07/15 22:31:50  188ED90 c [PRIORITIZE PID 3] 0624:000000:0F05 (found caid/provid in cache - weight: 1)
2014/07/15 22:31:50  188ED90 c [DVBAPI] found in channel cache: 0624&000000/0000/1F47/00:(null)
2014/07/15 22:31:50  188ED90 c [PRIORITIZE PID 3] 0624:000000:0F05 (found caid/provid/srvid in cache - weight: 2)
2014/07/15 22:31:50  188ED90 c [PRIORITIZE PID 3] 0624:000000:0F05:0000 (localrdr: skylink weight: 12)
2014/07/15 22:31:50  188ED90 c [IGNORE PID 1] 0D03:000000:0611:0000 (file)
2014/07/15 22:31:50  188ED90 c [IGNORE PID 0] 0D0F:000000:0651:0000 (file)
2014/07/15 22:31:50  188ED90 c [IGNORE PID 2] 0D96:000000:0F04:0000 (file)
2014/07/15 22:31:50  188ED90 c [IGNORE PID 4] 0666:000000:0122:0000 (file)
2014/07/15 22:31:50  188ED90 c [FORCED PID 3] 0624:000000:0F05:0000
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 trying to descramble PID #3 CAID 0624 PROVID 000000 ECMPID 0F05 ANY CHID VPID 00A6
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 try to start new filter for caid: 0624, provid: 000000, pid: 0F05
2014/07/15 22:31:50  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 15
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 Filter #2 started succesfully (caid 0624 provid 000000 pid 0F05)
2014/07/15 22:31:50  188ED90 c [DVBAPI] Demuxer #0 has 5 ecmpids, 3 streampids, 1 ecmfilters and 1 emmfilters
2014/07/15 22:31:51  188ED90 c receiving cat
2014/07/15 22:31:51  188ED90 c cat:
2014/07/15 22:31:51  188ED90    01 B0 DA FF FF D3 00 00 09 15 01 00 E0 C1 04 E2
2014/07/15 22:31:51  188ED90    C6 33 41 E2 BF 33 17 E2 BD 33 11 E2 BE 33 15 09
2014/07/15 22:31:51  188ED90    07 18 11 E0 C1 02 FE 22 09 07 18 11 E2 C6 02 33
2014/07/15 22:31:51  188ED90    41 09 07 18 11 E2 BF 02 33 17 09 07 18 11 E2 BE
2014/07/15 22:31:51  188ED90    02 33 15 09 07 18 11 E2 BD 02 33 11 09 09 18 63
2014/07/15 22:31:51  188ED90    E2 C7 04 33 42 33 43 09 0B 18 63 E2 C8 06 33 41
2014/07/15 22:31:51  188ED90    33 42 33 43 09 0C 05 00 E3 08 13 01 20 14 03 03
2014/07/15 22:31:51  188ED90    28 30 09 0C 05 00 E3 05 13 01 20 14 03 03 29 20
2014/07/15 22:31:51  188ED90    09 0C 05 00 E3 07 13 01 20 14 03 03 29 40 09 0C
2014/07/15 22:31:51  188ED90    05 00 E3 00 13 01 20 14 03 02 36 00 09 11 05 00
2014/07/15 22:31:51  188ED90    E3 04 13 01 20 14 03 03 0B 00 14 03 03 28 40 09
2014/07/15 22:31:51  188ED90    0C 05 00 E3 0C 13 01 20 14 03 04 33 30 09 0C 05
2014/07/15 22:31:51  188ED90    00 E3 0D 13 01 20 14 03 04 33 00 09 0C 05 00 E1
2014/07/15 22:31:51  188ED90    FE 13 01 20 14 03 04 26 30 25 DE DC 9B
2014/07/15 22:31:51  188ED90 c Reader skylink au enabled -> parsing cat for emm pids!
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 0100 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 1811 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 1863 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 1 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 0500 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 8 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 stop Filter #1 (fd: 14 api: 0, caid: 0001, provid: 000001, emmpid: 0001)
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 has 5 ecmpids, 3 streampids, 1 ecmfilters and 0 emmfilters
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 try to start new filter for caid: 0001, provid: 000001, pid: 0001
2014/07/15 22:31:51  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 14
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 Filter #1 started succesfully (caid 0001 provid 000001 pid 0001)
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 has 5 ecmpids, 3 streampids, 1 ecmfilters and 1 emmfilters
2014/07/15 22:31:51  188ED90 c receiving cat
2014/07/15 22:31:51  188ED90 c cat:
2014/07/15 22:31:51  188ED90    01 B0 DA FF FF D3 00 00 09 15 01 00 E0 C1 04 E2
2014/07/15 22:31:51  188ED90    C6 33 41 E2 BF 33 17 E2 BD 33 11 E2 BE 33 15 09
2014/07/15 22:31:51  188ED90    07 18 11 E0 C1 02 FE 22 09 07 18 11 E2 C6 02 33
2014/07/15 22:31:51  188ED90    41 09 07 18 11 E2 BF 02 33 17 09 07 18 11 E2 BE
2014/07/15 22:31:51  188ED90    02 33 15 09 07 18 11 E2 BD 02 33 11 09 09 18 63
2014/07/15 22:31:51  188ED90    E2 C7 04 33 42 33 43 09 0B 18 63 E2 C8 06 33 41
2014/07/15 22:31:51  188ED90    33 42 33 43 09 0C 05 00 E3 08 13 01 20 14 03 03
2014/07/15 22:31:51  188ED90    28 30 09 0C 05 00 E3 05 13 01 20 14 03 03 29 20
2014/07/15 22:31:51  188ED90    09 0C 05 00 E3 07 13 01 20 14 03 03 29 40 09 0C
2014/07/15 22:31:51  188ED90    05 00 E3 00 13 01 20 14 03 02 36 00 09 11 05 00
2014/07/15 22:31:51  188ED90    E3 04 13 01 20 14 03 03 0B 00 14 03 03 28 40 09
2014/07/15 22:31:51  188ED90    0C 05 00 E3 0C 13 01 20 14 03 04 33 30 09 0C 05
2014/07/15 22:31:51  188ED90    00 E3 0D 13 01 20 14 03 04 33 00 09 0C 05 00 E1
2014/07/15 22:31:51  188ED90    FE 13 01 20 14 03 04 26 30 25 DE DC 9B
2014/07/15 22:31:51  188ED90 c Reader skylink au enabled -> parsing cat for emm pids!
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 0100 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 1811 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 1863 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 1 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [IGNORE EMMPID] cardsystem for caid 0500 not found (ignoring)
2014/07/15 22:31:51        0   --- Skipped 8 duplicated log lines ---
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 stop Filter #1 (fd: 14 api: 0, caid: 0001, provid: 000001, emmpid: 0001)
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 has 5 ecmpids, 3 streampids, 1 ecmfilters and 0 emmfilters
2014/07/15 22:31:51  188ED90 c PMT Update on socket 7.
2014/07/15 22:31:51  188ED90 c New PMT info from socket (total size: 135)
2014/07/15 22:31:51  188ED90    9F 80 32 82 00 38 01 1F 47 00 00 23 01 82 02 00
2014/07/15 22:31:51  188ED90    01 09 04 0D 0F E6 51 09 04 0D 03 E6 11 09 04 0D
2014/07/15 22:31:51  188ED90    96 EF 04 09 04 06 24 EF 05 09 04 06 66 E1 22 02
2014/07/15 22:31:51  188ED90    00 A6 00 00 04 00 66 00 00 04 00 69 00 00 9F 80
2014/07/15 22:31:51  188ED90    32 82 00 43 02 1F 43 00 00 29 01 82 02 00 01 09
2014/07/15 22:31:51  188ED90    04 0D 0F E6 53 09 04 0D 03 E6 0F 09 04 0D 70 E7
2014/07/15 22:31:51  188ED90    01 09 04 0D 96 EF 00 09 04 06 24 EF 01 09 04 06
2014/07/15 22:31:51  188ED90    66 E0 26 02 00 A2 00 00 04 00 58 00 00 04 00 5B
2014/07/15 22:31:51  188ED90    00 00 04 00 62 00 00
2014/07/15 22:31:51  188ED90 c capmt:
2014/07/15 22:31:51  188ED90    01 1F 47 00 00 23 01 82 02 00 01 09 04 0D 0F E6
2014/07/15 22:31:51  188ED90    51 09 04 0D 03 E6 11 09 04 0D 96 EF 04 09 04 06
2014/07/15 22:31:51  188ED90    24 EF 05 09 04 06 66 E1 22 02 00 A6 00 00 04 00
2014/07/15 22:31:51  188ED90    66 00 00 04 00 69 00 00
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver sends PMT command 1 for channel 1F47
2014/07/15 22:31:51  188ED90 c [DVBAPI] Marked demuxer #0/16 to stop decoding
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F47 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 continue decoding of SRVID 1F47
2014/07/15 22:31:51  188ED90 c [pmt] type: 82 length: 2
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [SKIP STREAM 0] CAID: 0D0F ECM_PID: 0651 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [SKIP STREAM 1] CAID: 0D03 ECM_PID: 0611 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [SKIP STREAM 2] CAID: 0D96 ECM_PID: 0F04 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [SKIP STREAM 3] CAID: 0624 ECM_PID: 0F05 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [SKIP STREAM 4] CAID: 0666 ECM_PID: 0122 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 02 pid: 00a6 length: 0
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 04 pid: 0066 length: 0
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 04 pid: 0069 length: 0
2014/07/15 22:31:51  188ED90 c Found 5 ECMpids and 3 STREAMpids in PMT
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F47 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:51  188ED90 c New program number: 1F47 (0D0F:1F47 unknown) [pmt_list_management 1]
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #0 demux_index:  0 ca_mask: 02 program_info_length:  35 ca_pmt_list_management 01
2014/07/15 22:31:51  188ED90 c [DVBAPI] Parsing next PMT object(s):
2014/07/15 22:31:51  188ED90    9F 80 32 82 00 43 02 1F 43 00 00 29 01 82 02 00
2014/07/15 22:31:51  188ED90    01 09 04 0D 0F E6 53 09 04 0D 03 E6 0F 09 04 0D
2014/07/15 22:31:51  188ED90    70 E7 01 09 04 0D 96 EF 00 09 04 06 24 EF 01 09
2014/07/15 22:31:51  188ED90    04 06 66 E0 26 02 00 A2 00 00 04 00 58 00 00 04
2014/07/15 22:31:51  188ED90    00 5B 00 00 04 00 62 00 00
2014/07/15 22:31:51  188ED90 c capmt:
2014/07/15 22:31:51  188ED90    02 1F 43 00 00 29 01 82 02 00 01 09 04 0D 0F E6
2014/07/15 22:31:51  188ED90    53 09 04 0D 03 E6 0F 09 04 0D 70 E7 01 09 04 0D
2014/07/15 22:31:51  188ED90    96 EF 00 09 04 06 24 EF 01 09 04 06 66 E0 26 02
2014/07/15 22:31:51  188ED90    00 A2 00 00 04 00 58 00 00 04 00 5B 00 00 04 00
2014/07/15 22:31:51  188ED90    62 00 00
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver sends PMT command 2 for channel 1F43
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F43 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:51  188ED90 c [pmt] type: 82 length: 2
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 0] CAID: 0D0F ECM_PID: 0653 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 1] CAID: 0D03 ECM_PID: 060F PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 2] CAID: 0D70 ECM_PID: 0701 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 3] CAID: 0D96 ECM_PID: 0F00 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 4] CAID: 0624 ECM_PID: 0F01 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] type: 09 length: 4
2014/07/15 22:31:51  188ED90 c [ADD PID 5] CAID: 0666 ECM_PID: 0026 PROVID: 000000
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 02 pid: 00a2 length: 0
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 04 pid: 0058 length: 0
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 04 pid: 005b length: 0
2014/07/15 22:31:51  188ED90 c [pmt] stream_type: 04 pid: 0062 length: 0
2014/07/15 22:31:51  188ED90 c Found 6 ECMpids and 4 STREAMpids in PMT
2014/07/15 22:31:51  188ED90 c [DVBAPI] Receiver wants to demux srvid 1F43 on adapter 0001 camask 0002 index 0000
2014/07/15 22:31:51  188ED90 c New program number: 1F43 (0D0F:1F43 unknown) [pmt_list_management 2]
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 demux_index:  0 ca_mask: 02 program_info_length:  41 ca_pmt_list_management 02
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 try to start new filter for caid: 0001, provid: 000001, pid: 0001
2014/07/15 22:31:51  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 14
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 Filter #1 started succesfully (caid 0001 provid 000001 pid 0001)
2014/07/15 22:31:51  188ED90 c [PRIORITIZE PID 4] 0624:000000:0F01 (found caid/provid in cache - weight: 1)
2014/07/15 22:31:51  188ED90 c [DVBAPI] found in channel cache: 0624&000000/0000/1F43/00:(null)
2014/07/15 22:31:51  188ED90 c [PRIORITIZE PID 4] 0624:000000:0F01 (found caid/provid/srvid in cache - weight: 2)
2014/07/15 22:31:51  188ED90 c [PRIORITIZE PID 4] 0624:000000:0F01:0000 (localrdr: skylink weight: 14)
2014/07/15 22:31:51  188ED90 c [IGNORE PID 1] 0D03:000000:060F:0000 (file)
2014/07/15 22:31:51  188ED90 c [IGNORE PID 0] 0D0F:000000:0653:0000 (file)
2014/07/15 22:31:51  188ED90 c [IGNORE PID 3] 0D96:000000:0F00:0000 (file)
2014/07/15 22:31:51  188ED90 c [IGNORE PID 5] 0666:000000:0026:0000 (file)
2014/07/15 22:31:51  188ED90 c [FORCED PID 4] 0624:000000:0F01:0000
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 trying to descramble PID #4 CAID 0624 PROVID 000000 ECMPID 0F01 ANY CHID VPID 00A2
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 try to start new filter for caid: 0624, provid: 000000, pid: 0F01
2014/07/15 22:31:51  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 17
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 Filter #2 started succesfully (caid 0624 provid 000000 pid 0F01)
2014/07/15 22:31:51  188ED90 c [DVBAPI] Demuxer #1 has 6 ecmpids, 4 streampids, 1 ecmfilters and 1 emmfilters
2014/07/15 22:31:52  188ED90 c receiving cat
2014/07/15 22:31:52  188ED90 c cat:
2014/07/15 22:31:52  188ED90    01 B0 DA FF FF D3 00 00 09 15 01 00 E0 C1 04 E2
2014/07/15 22:31:52  188ED90    C6 33 41 E2 BF 33 17 E2 BD 33 11 E2 BE 33 15 09
2014/07/15 22:31:52  188ED90    07 18 11 E0 C1 02 FE 22 09 07 18 11 E2 C6 02 33
2014/07/15 22:31:52  188ED90    41 09 07 18 11 E2 BF 02 33 17 09 07 18 11 E2 BE
2014/07/15 22:31:52  188ED90    02 33 15 09 07 18 11 E2 BD 02 33 11 09 09 18 63
2014/07/15 22:31:52  188ED90    E2 C7 04 33 42 33 43 09 0B 18 63 E2 C8 06 33 41
2014/07/15 22:31:52  188ED90    33 42 33 43 09 0C 05 00 E3 08 13 01 20 14 03 03
2014/07/15 22:31:52  188ED90    28 30 09 0C 05 00 E3 05 13 01 20 14 03 03 29 20
2014/07/15 22:31:52  188ED90    09 0C 05 00 E3 07 13 01 20 14 03 03 29 40 09 0C
2014/07/15 22:31:52  188ED90    05 00 E3 00 13 01 20 14 03 02 36 00 09 11 05 00
2014/07/15 22:31:52  188ED90    E3 04 13 01 20 14 03 03 0B 00 14 03 03 28 40 09
2014/07/15 22:31:52  188ED90    0C 05 00 E3 0C 13 01 20 14 03 04 33 30 09 0C 05
2014/07/15 22:31:52  188ED90    00 E3 0D 13 01 20 14 03 04 33 00 09 0C 05 00 E1
2014/07/15 22:31:52  188ED90    FE 13 01 20 14 03 04 26 30 25 DE DC 9B
2014/07/15 22:31:52  188ED90 c Reader skylink au enabled -> parsing cat for emm pids!
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 0100 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 1811 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 1863 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 1 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 0500 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 8 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [DVBAPI] Demuxer #1 stop Filter #1 (fd: 14 api: 0, caid: 0001, provid: 000001, emmpid: 0001)
2014/07/15 22:31:52  188ED90 c [DVBAPI] Demuxer #1 has 6 ecmpids, 4 streampids, 1 ecmfilters and 0 emmfilters
2014/07/15 22:31:52  188ED90 c [DVBAPI] Demuxer #1 try to start new filter for caid: 0001, provid: 000001, pid: 0001
2014/07/15 22:31:52  188ED90 c DEVICE open (/dev/dvb/adapter1/demux0) fd 14
2014/07/15 22:31:52  188ED90 c [DVBAPI] Demuxer #1 Filter #1 started succesfully (caid 0001 provid 000001 pid 0001)
2014/07/15 22:31:52  188ED90 c [DVBAPI] Demuxer #1 has 6 ecmpids, 4 streampids, 1 ecmfilters and 1 emmfilters
2014/07/15 22:31:52  188ED90 c receiving cat
2014/07/15 22:31:52  188ED90 c cat:
2014/07/15 22:31:52  188ED90    01 B0 DA FF FF D3 00 00 09 15 01 00 E0 C1 04 E2
2014/07/15 22:31:52  188ED90    C6 33 41 E2 BF 33 17 E2 BD 33 11 E2 BE 33 15 09
2014/07/15 22:31:52  188ED90    07 18 11 E0 C1 02 FE 22 09 07 18 11 E2 C6 02 33
2014/07/15 22:31:52  188ED90    41 09 07 18 11 E2 BF 02 33 17 09 07 18 11 E2 BE
2014/07/15 22:31:52  188ED90    02 33 15 09 07 18 11 E2 BD 02 33 11 09 09 18 63
2014/07/15 22:31:52  188ED90    E2 C7 04 33 42 33 43 09 0B 18 63 E2 C8 06 33 41
2014/07/15 22:31:52  188ED90    33 42 33 43 09 0C 05 00 E3 08 13 01 20 14 03 03
2014/07/15 22:31:52  188ED90    28 30 09 0C 05 00 E3 05 13 01 20 14 03 03 29 20
2014/07/15 22:31:52  188ED90    09 0C 05 00 E3 07 13 01 20 14 03 03 29 40 09 0C
2014/07/15 22:31:52  188ED90    05 00 E3 00 13 01 20 14 03 02 36 00 09 11 05 00
2014/07/15 22:31:52  188ED90    E3 04 13 01 20 14 03 03 0B 00 14 03 03 28 40 09
2014/07/15 22:31:52  188ED90    0C 05 00 E3 0C 13 01 20 14 03 04 33 30 09 0C 05
2014/07/15 22:31:52  188ED90    00 E3 0D 13 01 20 14 03 04 33 00 09 0C 05 00 E1
2014/07/15 22:31:52  188ED90    FE 13 01 20 14 03 04 26 30 25 DE DC 9B
2014/07/15 22:31:52  188ED90 c Reader skylink au enabled -> parsing cat for emm pids!
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 0100 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 1811 not found (ignoring)
2014/07/15 22:31:52        0   --- Skipped 4 duplicated log lines ---
2014/07/15 22:31:52  188ED90 c [IGNORE EMMPID] cardsystem for caid 1863 not found (ignoring)

and so on...

I hope, this will shed some light on it. Regards Jan

manio commented 10 years ago

Jan, what XVDR version you are using? And please also tell me what and how many dvb cards you are using. A vdr command line (used plugins) would also be helpful...

jeanpijon commented 10 years ago

Hi Mariusz, sorry for delay, I was away from the box. from vdr log:

initializing plugin: xvdr (0.9.9): XVDR Server

vdr cmd:

 /usr/bin/vdr -v /srv/vdr/video.00 -c /var/lib/vdr -L /usr/lib/vdr/plugins -r /usr/lib/vdr/vdr-recordingaction -s /usr/lib/vdr/vdr-shutdown.wrapper -E /var/cache/vdr/epg.data -u vdr -g /tmp --port 6419 --resdir=/usr/share/vdr --cachedir=/var/cache/vdr --dirnames=,,1 -w 0 -P restfulapi --port=8002 --ip=0.0.0.0 --epgimages=/var/cache/vdr/epgimages --channellogos=/usr/share/vdr-channellogos -P quickepgsearch -P streamdev-server -P dvbsddevice -P dvbhddevice -P vnsiserver -t 10 -P xineliboutput --local=none --primary --remote=127.0.0.1:37890 --truecolor -P dbus2vdr --shutdown-hooks=/usr/share/vdr/shutdown-hooks --shutdown-hooks-wrapper=/usr/share/vdr-plugin-dbus2vdr/shutdown-wrapper --upstart -P xvdr -t 10 -P epgsearch -f /usr/bin/svdrpsend -P conflictcheckonly -P dvbapi -P live --port=8008 --ip=0.0.0.0 --log=INFO --epgimages=/var/cache/vdr/epgimages -P epgsearchonly

two DVB cards

root@htpc:~# dmesg | grep -i dvb
[   18.432260] DVB: registering new adapter (FlexCop Digital TV device)
[   19.106909] b2c2-flexcop: found 'Zarlink MT352 DVB-T' .
[   19.106914] DVB: registering adapter 0 frontend 0 (Zarlink MT352 DVB-T)...
[   19.106986] b2c2-flexcop: initialization of 'Air2PC/AirStar 2 DVB-T' at the 'PCI' bus controlled by a 'FlexCopIIb' complete
[   19.298175] cx88[0]: subsystem: d464:9022, board: TeVii S464 DVB-S/S2 [card=86,autodetected], frontend(s): 1
[   20.100210] input: cx88 IR (TeVii S464 DVB-S/S2) as /devices/pci0000:00/0000:00:14.4/0000:03:07.2/rc/rc1/input14
[   20.100262] rc1: cx88 IR (TeVii S464 DVB-S/S2) as /devices/pci0000:00/0000:00:14.4/0000:03:07.2/rc/rc1
[   20.280962] cx88/2: cx2388x dvb driver version 0.0.9 loaded
[   20.280966] cx88/2: registering cx8802 driver, type: dvb access: shared
[   20.280969] cx88[0]/2: subsystem: d464:9022, board: TeVii S464 DVB-S/S2 [card=86]
[   20.280972] cx88[0]/2: cx2388x based DVB/ATSC card
[   20.398451] DVB: registering new adapter (cx88[0])
[   20.398454] DVB: registering adapter 1 frontend 0 (Montage Technology DS3000/TS2020)...
[   26.516694] ds3000_firmware_ondemand: Waiting for firmware upload (dvb-fe-ds3000.fw)...
manio commented 10 years ago

I think the problem is in this case with your XVDR plugin. At least from the logs it seems like this. You was compiling XVDR yourself? I don't know if the needed changes are in your plugin (I cannot state it from your xvdr version string). The changes started from this commit: https://github.com/pipelka/vdr-plugin-xvdr/commit/d90c0912bb14411aa7252ae7bf41e527a6e97f88 Make sure you have it.

Second tip: please try to run it with only minimal set of needed plugins. I can see you have probably all available VDR plugins loaded! :) Eg: do you really using streamdev-server and vnsiserver and xvdrserver in the same time??? For my vdr it is sufficient to run: ./vdr -Pdvbapi -Pxvdr and that's all what I need. More unneeded plugins you have loaded, more troubles you can have.

jeanpijon commented 10 years ago

Hi Mariusz, I will try to compile it from git and report back.

To the plugins, yep, I am using even streamdev for webfrontend, maybe vnsi could be disabled. In fact, I didn't make any changes from YaVDR default configuration of vdr plugins. but I will try to clean it up a bit. I will report back soon with results from latest version.

jeanpijon commented 10 years ago

OK, after compiling xvdr plugin from git and removing one unneeded dvb card, it seems to work, question is, what was the cause... Anyway - I will try to monitor it. Thanks a lot for helping me to solve this problem! You are doing a hell of work here! We all appreciate it a lot! Thanks again. Jan

manio commented 10 years ago

You probably had xvdr without needed changes (as I mentioned above) and it was giving up too early. Thank you, closing.

jeanpijon commented 9 years ago

So I double checked, and this was not the issue - it is still not able to switch from FTA back to encrypted channels :(

manio commented 9 years ago

The same problem in the log? If so it is a XVDR problem probably as my plugin is not receiving CAM decrypt request from VDR.

jeanpijon commented 9 years ago

it seems, that error is this time somehow different, vdr doesn't timeout like before, but still no channel is descrambled... I am curious if it is not some problem with sync issue between dvbapi and oscam (see that new fd connection), but what is completely cryptic for me is that decoding request restart in oscam - it goes forever after sitch to encrypted channels...

Oct  5 17:55:33 htpc vdr: [4598] CAM 1: assigned to device 1
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Found available device 1
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Channel information found in cache
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Creating demuxers
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Stream: MPEG2VIDEO PID: 3201 720x576 DAR: 1,78 FPS: 25,000 (parsed: yes)
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Stream: MPEG2AUDIO PID: 3202 48000 Hz, 2 channels, Lang: cze (parsed: yes)
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Stream: TELETEXT PID: 3203 TXT (parsed: yes)
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Successfully switched to channel 3 - Nova
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: 0.0 CA_PMT decoding len=23 lm=4 prg=13138 len=13
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: ci_cmd(G)=01
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: pid=2,0c81 len=0 (0x0)
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: pid=4,0c82 len=0 (0x0)
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: 0.0 got CA pmt ciCmd=1 caLm=4
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: 0.0 answer to query suppressed
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: 0.0 set CAM decrypt (SID 13138, caLm 4, HasCaDescriptors 1)
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: send: channelSid=0x3352 (13138)
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: created socket with socket_fd=34
Oct  5 17:55:33 htpc vdr: [4598] DVBAPI: socket_fd=34 len=45 wrote=45
Oct  5 17:55:33 htpc vdr: [4598] XVDR: Starting PAT scanner
Oct  5 17:55:33 htpc vdr: [4598] XVDR: done switching.
Oct  5 17:55:33 htpc vdr: [4600] receiver on device 1 thread started (pid=4232, tid=4600, prio=high)
Oct  5 17:55:33 htpc vdr: [4601] TS buffer on device 1 thread started (pid=4232, tid=4601, prio=high)

oscam.log

2014/10/05 17:55:22  2364180 c vdr (0624&000000/0000/3352/59:60377096A8959E2E078A07D131672B07): found (159 ms) by skylink - Nova
2014/10/05 17:55:33  2364180 c [DVBAPI] Receiver sends PMT command 3 for channel 3352
2014/10/05 17:55:33  2364180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0000 camask 0001 index 0000
2014/10/05 17:55:33  2364180 c [ADD PID 0] CAID: 0D96 ECM_PID: 0F0E PROVID: 000000
2014/10/05 17:55:33  2364180 c [ADD PID 1] CAID: 0624 ECM_PID: 0F0F PROVID: 000000
2014/10/05 17:55:33  2364180 c [ADD PID 2] CAID: 0666 ECM_PID: 005B PROVID: 000000
2014/10/05 17:55:33  2364180 c Found 3 ECMpids and 2 STREAMpids in PMT
2014/10/05 17:55:33  2364180 c [DVBAPI] Receiver wants to demux srvid 3352 on adapter 0000 camask 0001 index 0000
2014/10/05 17:55:33  2364180 c New program number: 3352 (Nova) [pmt_list_management 3]
2014/10/05 17:55:33  2364180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/10/05 17:55:36  2364180 c [DVBAPI] Demuxer #0 (re)starting decodingrequests on all 3 ecmpids!
2014/10/05 17:55:36  2364180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/10/05 17:55:39  2364180 c [DVBAPI] Demuxer #0 (re)starting decodingrequests on all 3 ecmpids!
2014/10/05 17:55:40  2364180 c [DVBAPI] Demuxer #0 trying to descramble PID #1 CAID 0624 PROVID 000000 ECMPID 0F0F ANY CHID VPID 0C81
2014/10/05 17:55:43  2364180 c [DVBAPI] Demuxer #0 (re)starting decodingrequests on all 3 ecmpids!
manio commented 9 years ago

I don't see nothing unusual in the VDR log. VDR is always creating a new connection when doing switch to a channel (even when you are zapping). Moreover: if VDR cannot start decoding it is doing stop and start again for the same channel and you'll also see a new connection in the OSCam log.

Regarding your problem: In the oscam log however is indeed trying to restart decoding request. It is probably because it cannot obtain the ECM. One way or another I think you rather should ask on OSCam forum for this, because I don't see any problem in the plugin (it is working as expected, providing PMT data and waiting for the keys from OSCam, which the later cannot provide).

locka-hd commented 9 years ago

how to fix that 2015/05/21 04:38:34 1013E970 c (reader) casca [seca] EMM: reader_caid 0100 != emmpid caid 1839 -> SKIP!