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
58 stars 25 forks source link

vdr stops trying to get key #3

Closed ghost closed 12 years ago

ghost commented 12 years ago

Im saying vdr and not dvb-api because im not sure which is at fault there or even softhddevice. If i leave oscam idle it by default disconnects clients.Then if i try to tune to a channel it will fail the first time even though it will eventually connect and get an ecm reply from a peer.Softhddevice logs indicate it still receives scrambled packets.I have to switch to another channel and then back on to work correctly.Same thing happens if i have bad signal on a channel, ie it will stop and never come back until i switch back and forth.

manio commented 12 years ago

Hi! I am unable to tell you what is wrong without a full debug log.

ghost commented 12 years ago

is that ok? tell me if you need more "switching to channel 88" is the encrypted channel trying to open on the first time(oscam needs to connect because it's idle) if i switch to another channel and back it will work.In the mean time subtitles play in black the background

May 19 20:06:43 mythbox vdr: video/vdpau: VDPAU API version: 1 May 19 20:06:43 mythbox vdr: video/vdpau: VDPAU information: NVIDIA VDPAU Driver Shared Library 295.40 Thu Apr 5 21:54:31 PDT 2012 May 19 20:06:43 mythbox vdr: video/vdpau: high quality scaling unsupported May 19 20:06:43 mythbox vdr: video/vdpau: feature deinterlace temporal supported May 19 20:06:43 mythbox vdr: video/vdpau: feature deinterlace temporal spatial supported May 19 20:06:43 mythbox vdr: video/vdpau: attribute skip chroma deinterlace supported May 19 20:06:43 mythbox vdr: video/vdpau: 4:2:0 chroma format with 4096x4096 supported May 19 20:06:43 mythbox vdr: video/vdpau: 4:2:2 chroma format with 4096x4096 supported May 19 20:06:43 mythbox vdr: video/vdpau: 8bit BGRA format with 8192x8192 supported May 19 20:06:43 mythbox vdr: video/vdpau: 10bit RGBA format with 8192x8192 supported May 19 20:06:43 mythbox vdr: audio: 'alsa' output module used May 19 20:06:43 mythbox vdr: audio/alsa: supports pause: no May 19 20:06:43 mythbox vdr: audio: 44100Hz supports 1 2 3 4 5 6 7 8 channels May 19 20:06:43 mythbox vdr: audio: 48000Hz supports 1 2 3 4 5 6 7 8 channels May 19 20:06:43 mythbox vdr: [6363] closing SVDRP connection May 19 20:06:43 mythbox vdr: audio/alsa: using device 'default' May 19 20:06:43 mythbox vdr: audio/alsa: start delay 336ms May 19 20:06:44 mythbox vdr: [6363] connect from 127.0.0.1, port 51560 - accepted May 19 20:06:44 mythbox vdr: [6363] closing SVDRP connection May 19 20:06:45 mythbox vdr: [29742] Text2Skin: menu display update thread started (pid=6363, tid=29742) May 19 20:06:54 mythbox vdr: [29742] Text2Skin: menu display update thread ended (pid=6363, tid=29742) May 19 20:07:08 mythbox vdr: [29745] Text2Skin: channelInfo display update thread started (pid=6363, tid=29745) May 19 20:07:16 mythbox vdr: [29745] Text2Skin: channelInfo display update thread ended (pid=6363, tid=29745) May 19 20:07:44 mythbox vdr: video: 10:40:43.541 +23 326 0/\ms 42 v-buf May 19 20:08:12 mythbox vdr: [6363] DVBAPI: 0.0 CA_PMT decoding len=6 lm=3 prg=0 len=0 May 19 20:08:12 mythbox vdr: [6363] DVBAPI: 0.0 got CA pmt ciCmd=-1 caLm=3 May 19 20:08:12 mythbox vdr: [6363] DVBAPI: SetChannelDevice May 19 20:08:13 mythbox vdr: [29767] Text2Skin: channelInfo display update thread started (pid=6363, tid=29767) May 19 20:08:21 mythbox vdr: [6363] switching to channel 88 May 19 20:08:21 mythbox vdr: [6363] [softhddev]SetPlayMode: 0 May 19 20:08:21 mythbox vdr: [6363] [softhddev]SetVideoDisplayFormat: 1 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [24243] DVBAPI: CloseDvr May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetChannelDevice May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=1 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=1 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=1 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: SetPid: on=1 May 19 20:08:21 mythbox vdr: [24244] TS buffer on device 2 thread ended (pid=6363, tid=24244) May 19 20:08:21 mythbox vdr: [24243] DVBAPI: 1: reset state May 19 20:08:21 mythbox vdr: [24243] DVBAPI: 1: set active off May 19 20:08:21 mythbox vdr: [24243] buffer stats: 80464 (1%) used May 19 20:08:21 mythbox vdr: [24243] receiver on device 2 thread ended (pid=6363, tid=24243) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: 0.0 CA_PMT decoding len=53 lm=4 prg=6502 len=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: pid=2,090d len=19 (0x13) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ci_cmd(S)=01 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: pid=4,090f len=19 (0x13) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ci_cmd(S)=01 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: pid=4,0911 len=19 (0x13) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ci_cmd(S)=01 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: pid=6,090e len=0 (0x0) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: 0.0 got CA pmt ciCmd=1 caLm=4 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: 0.0 set CAM decrypt (SID 6502, caLm 4, HasCaDescriptors 1) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: ProcessSIDRequest: added: i=0 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: channelSid=0x1966(6502) May 19 20:08:21 mythbox vdr: [6363] DVBAPI: created socket with socket_fd=27 May 19 20:08:21 mythbox vdr: [6363] DVBAPI: socket_fd=27 length=83 toWrite=94 wrote=94 May 19 20:08:21 mythbox vdr: [29769] receiver on device 1 thread started (pid=6363, tid=29769) May 19 20:08:21 mythbox vdr: [29769] DVBAPI: OpenDvr May 19 20:08:21 mythbox vdr: [29769] DVBAPI: CloseDvr May 19 20:08:21 mythbox vdr: [29769] DVBAPI: ScActive May 19 20:08:21 mythbox vdr: [29769] DVBAPI: 0: set active on May 19 20:08:21 mythbox vdr: [29770] TS buffer on device 1 thread started (pid=6363, tid=29770) May 19 20:08:21 mythbox vdr: [24245] ttxtsubs player thread ended (pid=6363, tid=24245) May 19 20:08:21 mythbox vdr: [6363] buffer stats: 0 (0%) used May 19 20:08:21 mythbox vdr: [6363] ttxtsubs: teletext subtitles replayer started with initial page 000 May 19 20:08:21 mythbox vdr: [6363] [softhddev]SetPlayMode: 1 May 19 20:08:21 mythbox vdr: [29771] ttxtsubs player thread started (pid=6363, tid=29771) May 19 20:08:21 mythbox vdr: [29769] Found subtitle page: 888 May 19 20:08:21 mythbox vdr: audio/alsa: using device 'default' May 19 20:08:21 mythbox vdr: audio/alsa: start delay 336ms May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:22 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:23 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:24 mythbox vdr: video: decoder buffer empty, duping frame (6/4850) 0 v-buf May 19 20:08:24 mythbox vdr: video: --:--:--.--- +0 0 0/\ms 0 v-buf May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:25 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [29767] Text2Skin: channelInfo display update thread ended (pid=6363, tid=29767) May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:26 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:27 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:28 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:29 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:30 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:31 mythbox vdr: [6379] DVBAPI: Action: Got CA_SET_DESCR request May 19 20:08:31 mythbox vdr: [6379] DVBAPI: DeCSASetCaDescr: index=-1 May 19 20:08:31 mythbox vdr: [6379] DVBAPI: DeCSASetCaDescr: removal request - ignoring May 19 20:08:32 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:32 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:32 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:32 mythbox vdr: [softhddev] invalid PES video packet May 19 20:08:32 mythbox vdr: [softhddev] invalid PES video packet

manio commented 12 years ago

The problem is that oscam does not provide keys back to dvbapi plugin (after sending PMT data). It is not dvbapi plugin problem.

ghost commented 12 years ago

i checked the oscam logs and it seems oscam thinks it does send back a key

May 19 21:30:52 mythbox oscam: :51 81E01A8 p tcp_conn_close(): fd=7, cl->typ == 'p' is_udp 0 label == '' reason inactivity May 19 21:55:07 mythbox oscam: :07 81E3400 p tcp_conn_close(): fd=8, cl->typ == 'p' is_udp 0 label == '' reason inactivity May 19 22:05:59 mythbox oscam: :58 81EE540 c dvbapi: [ADD PID 0] CAID: 0960 ECM_PID: 0501 PROVID: 000000 May 19 22:05:59 mythbox oscam: :58 81EE540 c dvbapi: [ADD PID 1] CAID: 0961 ECM_PID: 0501 PROVID: 000000 May 19 22:05:59 mythbox oscam: :58 81EE540 c dvbapi: [ADD PID 2] CAID: 0963 ECM_PID: 0501 PROVID: 000000 May 19 22:05:59 mythbox oscam: :58 81EE540 c dvbapi: new program number: 1966 (0960:1966 unknown) [pmt_list_management 3] May 19 22:05:59 mythbox oscam: :59 81E01A8 p connecting to on :12005 May 19 22:05:59 mythbox oscam: :59 81E01A8 p socket open for cccam fd=13 May 19 22:05:59 mythbox oscam: :59 81E01A8 p connect succesfull cccam fd=13 May 19 22:05:59 mythbox oscam: :59 81E3400 p connecting to on :28800 May 19 22:05:59 mythbox oscam: :59 81E3400 p socket open for cccam fd=15 May 19 22:06:02 mythbox oscam: :02 81E3400 p connect(fd=15) failed: (errno=110 Connection timed out) May 19 22:06:02 mythbox oscam: :02 81E3400 p network connect error! May 19 22:06:02 mythbox oscam: :02 81E3400 p connecting to on :28800 May 19 22:06:02 mythbox oscam: :02 81E3400 p socket open for cccam fd=15 May 19 22:06:03 mythbox oscam: :03 81E3400 p connect succesfull cccam fd=15 May 19 22:06:04 mythbox oscam: :04 81EE540 c vdr (0963&000000/0000/1966/62:727F): timeout (5000 ms) by (2 of 2) May 19 22:06:07 mythbox oscam: :07 81EE540 c vdr (0963&000000/0000/1966/62:775C): timeout (5005 ms) May 19 22:06:10 mythbox oscam: :10 81EE540 c vdr (0963&000000/0000/1966/62:67C7): found (315 ms) by

manio commented 12 years ago

Maybe you need more detailed oscam log to inspect this. The dvbapi should have CA_SET_DESCR with index != -1 and it doesn't got it.

ghost commented 12 years ago

May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: dvbapi request cw for snipped May 20 00:20:20 mythbox oscam: :20 81EE540 c reader unavailable May 20 00:20:20 mythbox oscam: :20 81EE540 c vdr (sniped): rejected group (1 ms) (0 of 0) (no matching reader) May 20 00:20:20 mythbox oscam: :20 81EE540 c cw: May 20 00:20:20 mythbox oscam: :20 81EE540 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: auto disable filter #0 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: dvbapi request cw for May 20 00:20:20 mythbox oscam: :20 81EE540 c reader unavailable May 20 00:20:20 mythbox oscam: :20 81EE540 c vdr (snipped): rejected group (0 ms) (0 of 0) (no matching reader) May 20 00:20:20 mythbox oscam: :20 81EE540 c cw: May 20 00:20:20 mythbox oscam: :20 81EE540 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: auto disable filter #1 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: dvbapi request cw for snipped May 20 00:20:20 mythbox oscam: :20 81EE540 c request_cw stage=3 to reader ecm=snipped May 20 00:20:20 mythbox oscam: :20 81EE540 c add reader job action 5 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: auto disable filter #2 May 20 00:20:20 mythbox oscam: :20 81E3400 p poll wakeup May 20 00:20:20 mythbox oscam: :20 81E3400 p ---- ecm_task 0, idx 79, sflag=1, level=0 May 20 00:20:20 mythbox oscam: :20 81E3400 p casc ecm: snipped May 20 00:20:20 mythbox oscam: :20 81E3400 p data on socket May 20 00:20:20 mythbox oscam: :20 81E3400 p start client thread action 24 May 20 00:20:20 mythbox oscam: :20 81EE540 c data from add_job action=24 client c vdr May 20 00:20:20 mythbox oscam: :20 81EE540 c ecm answer from reader for ecm E530 rc=0 May 20 00:20:20 mythbox oscam: :20 81EE540 c dvbapi: write cw0 index: -1 (ca0) May 20 00:20:20 mythbox oscam: :20 81EE540 c vdr (snipped): found (263 ms) by May 20 00:20:20 mythbox oscam: :20 81EE540 c cw: May 20 00:20:20 mythbox oscam: :20 81EE540 snipped May 20 00:20:20 mythbox oscam: :20 81EE540 c ending thread May 20 00:20:29 mythbox oscam: :29 81E3400 p add reader job action 1 May 20 00:20:40 mythbox oscam: :40 841A1A0 c data on socket

manio commented 12 years ago

This is the only CA_SET_DESCR request from oscam: dvbapi: write cw0 index: -1 (ca0) And it is a removal request, because index = -1

Please open ticket in oscam. It is not dvbapi plugin problem.

ghost commented 12 years ago

you are right, for reference it seems to be this bug http://streamboard.gmc.to:8001/ticket/2479 and the workaround is setting request mode 0