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

Channel switching takes 1 min #134

Closed REELcoder closed 4 years ago

REELcoder commented 4 years ago

When switching to crypted channel, the first attempt usually takes 1 min to start reception:

Nov 10 10:43:00 core vdr: [23124] switching to channel 1 S13.0E-318-12300-17201 (SRF 1 HD)
Nov 10 10:43:00 core vdr: [23124] [softhddev]SetPlayMode: 0
Nov 10 10:43:01 core vdr: [23124] [softhddev]SetVideoDisplayFormat: 1
Nov 10 10:43:01 core vdr: [23124] [softhddev]GetSpuDecoder:
Nov 10 10:43:01 core vdr: [28246] device 1 receiver thread ended (pid=23124, tid=28246)
Nov 10 10:43:01 core vdr: [23124] CAM 1: assigned to device 1
Nov 10 10:43:01 core vdr: [28903] device 1 receiver thread started (pid=23124, tid=28903, prio=high)
Nov 10 10:43:01 core vdr: [23127] SATIP: Detected 2 RTP packet errors [device 0]
Nov 10 10:43:01 core vdr: [23124] DVBAPI: 0.0 CA_PMT decoding len=a6 lm=4 prg=17201 len=0
Nov 10 10:43:01 core vdr: [23124] DVBAPI: pid=2,01f6 len=35 (0x23)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: ci_cmd(S)=01
Nov 10 10:43:01 core vdr: [23124] DVBAPI: pid=4,01f7 len=35 (0x23)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: ci_cmd(S)=01
Nov 10 10:43:01 core vdr: [23124] DVBAPI: pid=4,01f8 len=35 (0x23)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: ci_cmd(S)=01
Nov 10 10:43:01 core vdr: [23124] DVBAPI: pid=6,01f9 len=35 (0x23)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: ci_cmd(S)=01
Nov 10 10:43:01 core vdr: [23124] DVBAPI: 0.0 got CA pmt ciCmd=1 caLm=4
Nov 10 10:43:01 core vdr: [23124] DVBAPI: 0.0 answer to query suppressed
Nov 10 10:43:01 core vdr: [23124] DVBAPI: 0.0 set CAM decrypt (SID 17201 (0x4331), caLm 4, HasCaDescriptors 1)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: send: channelSid=0x4331 (17201)
Nov 10 10:43:01 core vdr: [23124] DVBAPI: Write, sock=61
Nov 10 10:43:01 core vdr: [23124] DVBAPI: socket_fd=61 len=177 wrote=177
Nov 10 10:43:01 core vdr: [23124] [softhddev]SetPlayMode: 1
Nov 10 10:43:01 core vdr: [23146] DVBAPI: Action: Got DMX_SET_FILTER request, adapter_index=0, pid=0, demux_idx=0, filter_num=0
Nov 10 10:43:01 core vdr: [23146] DVBAPI: SetFilter: adapter=0 set FILTER pid=0000 start=1, demux=0, filter=0
Nov 10 10:43:01 core vdr: [23146] DVBAPI:    --> FILTER: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:01 core vdr: [23146] DVBAPI:    -->   MASK: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:01 core vdr: [23146] DVBAPI: SetFilter: inserting new filter, demux=0, filter_num=0
Nov 10 10:43:01 core vdr: [23146] DVBAPI: Action: Got DMX_SET_FILTER request, adapter_index=0, pid=2E3, demux_idx=0, filter_num=1
Nov 10 10:43:01 core vdr: [23146] DVBAPI: SetFilter: adapter=0 set FILTER pid=02E3 start=1, demux=0, filter=1
Nov 10 10:43:01 core vdr: [23146] DVBAPI:    --> FILTER: 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:01 core vdr: [23146] DVBAPI:    -->   MASK: F0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:01 core vdr: [23146] DVBAPI: SetFilter: inserting new filter, demux=0, filter_num=1
Nov 10 10:43:21 core vdr: [23146] DVBAPI: Action: Got DMX_SET_FILTER request, adapter_index=0, pid=1, demux_idx=0, filter_num=2
Nov 10 10:43:21 core vdr: [23146] DVBAPI: SetFilter: adapter=0 set FILTER pid=0001 start=1, demux=0, filter=2
Nov 10 10:43:21 core vdr: [23146] DVBAPI:    --> FILTER: 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:21 core vdr: [23146] DVBAPI:    -->   MASK: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:43:21 core vdr: [23146] DVBAPI: SetFilter: inserting new filter, demux=0, filter_num=2
Nov 10 10:43:21 core vdr: [28903] DVBAPI: Analyze: all data in one TS packet, immediate send
Nov 10 10:43:21 core vdr: [28903] DVBAPI: Write, sock=61
Nov 10 10:43:21 core vdr: [28903] DVBAPI: socket_fd=61 len=36 wrote=36
Nov 10 10:43:21 core vdr: [23146] DVBAPI: Action: Got DMX_STOP request, adapter_index=0, pid=1, demux_idx=0, filter_num=2
Nov 10 10:43:21 core vdr: [23146] DVBAPI: SetFilter: adapter=0 set FILTER pid=0001 start=0, demux=0, filter=2
Nov 10 10:43:21 core vdr: [23146] DVBAPI: SetFilter: deleting filter, demux=0, filter_num=2
Nov 10 10:43:21 core vdr: [23146] DVBAPI: SetFilter: deleted the last filter for pid=0001, removing list
Nov 10 10:43:29 core vdr: video: --:--:--.---   +0    0   0/\ms   0+0+4 v-buf
Nov 10 10:44:01 core vdr: [23128] SATIP-ERROR: Detected invalid status code 404: rtsp://10.76.1.180/ [device 0]
Nov 10 10:44:01 core vdr: [23128] SATIP-ERROR: Keep-alive failed - retuning [device 0]
Nov 10 10:44:01 core vdr: [23128] SATIP-ERROR: Detected invalid status code 400: rtsp://10.76.1.180/ [device 0]
Nov 10 10:44:01 core vdr: [23128] SATIP-ERROR: Connect failed [device 0]
Nov 10 10:44:02 core vdr: audio/alsa: using device 'downmix'
Nov 10 10:44:02 core vdr: audio/alsa: start delay 500ms
Nov 10 10:44:02 core vdr: [28903] DVBAPI: Analyze: all data in one TS packet, immediate send
Nov 10 10:44:02 core vdr: [28903] DVBAPI: Write, sock=61
Nov 10 10:44:02 core vdr: [28903] DVBAPI: socket_fd=61 len=48 wrote=48
Nov 10 10:44:02 core vdr: [softhddev] invalid PES video packet
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got DMX_SET_FILTER request, adapter_index=0, pid=2E3, demux_idx=0, filter_num=1
Nov 10 10:44:02 core vdr: [23146] DVBAPI: SetFilter: adapter=0 set FILTER pid=02E3 start=1, demux=0, filter=1
Nov 10 10:44:02 core vdr: [23146] DVBAPI:    --> FILTER: 81 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:44:02 core vdr: [23146] DVBAPI:    -->   MASK: FF 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Nov 10 10:44:02 core vdr: [23146] DVBAPI: SetFilter: filter update, demux=0, filter_num=1
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.-1: set pid 0x01f6
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.0: set pid 0x01f6
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.-1: set pid 0x01f7
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.0: set pid 0x01f7
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.-1: set pid 0x01f8
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.0: set pid 0x01f8
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.-1: set pid 0x01f9
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_PID request, adapter_index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0.0: set pid 0x01f9
Nov 10 10:44:02 core vdr: [23146] DVBAPI: SetDescr
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0: even key set
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_DESCR request, adapter_index=0, index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: SetDescr
Nov 10 10:44:02 core vdr: [23146] DVBAPI: 0:  odd key set
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got CA_SET_DESCR request, adapter_index=0, index=0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: Action: Got ECM_INFO: adapter_index=0, SID = 4331, CAID = 0500 (viaccess), PID = 02E3, ProvID = 050800, ECM time = 188 ms, reader = srg_v5, from = local, protocol = smargo, hops = 0
Nov 10 10:44:02 core vdr: [23146] DVBAPI: UpdateEcmInfo: PMTO update, adapter=0, SID=4331
Nov 10 10:44:03 core vdr: [softhddev] 15 invalid PES video packet(s)
Nov 10 10:44:04 core vdr: video: slow down video, duping frame
Nov 10 10:44:04 core vdr: video: 16:25:24.201 +107  507   0/\ms  43+4+4 v-buf
Nov 10 10:44:04 core vdr: video/vdpau: synced after 59 frames

Switching to a non-crypted channel has no issues.

This is vdr-2.4.1 with satip git cd1f00c

ua0lnj commented 4 years ago

Oscam version?

REELcoder commented 4 years ago

r11273

I asume it should be fine with cd1f00c

ua0lnj commented 4 years ago

Oldest version of dvbapi plugin works better? If so, can you find a commit after which it gets worse? Or always has been? I don’t know the peculiarities of viaccess, do other access systems work like that too? I use 0x2600 and 0x0501, it's works fine. And can you test without satip, or other version of satip. Please give more info.

REELcoder commented 4 years ago

I had no issues with vdr-2.2.0 and dvbapi 7a42b22. Tried older versions of both satip and dvbapi with no better result. Could therefore also an issue with VDR itself. But I have no idea how to debug.

REELcoder commented 4 years ago

satip is out. It is not called to receive PIDs. The channel get's tunned 1 min later as well.

REELcoder commented 4 years ago

Do I get it right: "Got DMX_SET_FILTER request" is from SocketHandler and this happens uppon request from oscam?

oscam has from this point in time the followin in the log

2019/11/10 10:43:01 2D57C9B2 c   (dvbapi) Demuxer 0 ecmpid 0 CAID: 0500 ECM_PID: 02ED PROVID: 060200 
2019/11/10 10:43:01 2D57C9B2 c   (dvbapi) Demuxer 0 ecmpid 1 CAID: 0500 ECM_PID: 02E3 PROVID: 050800 
2019/11/10 10:43:01 2D57C9B2 c   (dvbapi) Demuxer 0 found 2 ECMpids and 4 STREAMpids in caPMT
2019/11/10 10:43:01 2D57C9B2 c   (dvbapi) Demuxer 0 found channel in cache and matching prio -> start descrambling ecmpid 1 
2019/11/10 10:43:01 2D57C9B2 c   (dvbapi) Demuxer 0 trying to descramble PID 1 CAID 0500 PROVID 050800 ECMPID 02E3 ANY CHID PMTPID 0000 VPID 01F6
2019/11/10 10:44:02 2D57C9B2 c      (ecm) reel (0500@050800/08E2/4331/2A:D03DE2FD662A3D0A4527691D2D54BF13): found (188 ms) by srg_v5 - SRF 1 HD
2019/11/10 10:44:05 2D57C9B2 c      (ecm) reel (0500@050800/08E2/4331/2A:1DA8EEBD559096D6BF6B0E53A4C875B9): found (189 ms) by srg_v5 - SRF 1 HD
2019/11/10 10:44:15 2D57C9B2 c      (ecm) reel (0500@050800/08E2/4331/2A:BBF7B4583380E917BC2D86AA4269F808): found (189 ms) by srg_v5 - SRF 1 HD

PID 0x02E3 would be the correct one for this channel. At the same point in time no AddPids call is happening on the satip-plugin...

Something faills between here and satip.

Strange is that after exaclty 1 min the reception starts normally...

ua0lnj commented 4 years ago

May be worth writing on the Oscam's forum? And see Oscam log too.

REELcoder commented 4 years ago

I changed from vdr-2.2.0 to vdr-2.4.1. With 2.2 there was no issue with oscam and updating oscam did not change the behaviour. I assume there is an issue with vdr or dvbapi-plugin. When I updated vdr to 2.4.1, I switched dvbapi from the 2.2 branch to the master branch.

The above oscam log does not show any activity between 10:43:01 and 10:44:02. After this 1 minute the reception starts.

I can also force to have reception earlier than after 1 minute by just switching to the same channel 2-3 times.

Any hints how I can debug this?

ua0lnj commented 4 years ago

You set Oscam debug log to all?

REELcoder commented 4 years ago

Here is a more detailed oscam log (reader stuff/webif/threads deleted):

2019/11/15 18:28:30 266B55F4 c   (dvbapi) New events occurred on 1 of 2 handlers after 2310221 ms inactivity
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Now handling fd 13 that reported event 1
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Try reading 4 bytes from connection fd 13
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Got packetdata (msgid size: 0, clientprotocol: 2)
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   9F 80 32 82 00 AB 03 43 31 00 00 05 01 82 02 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 02 01 F6 00 23 01 09 0F 05 00 E2 ED 10 01 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   13 01 20 14 03 06 02 08 09 0F 05 00 E2 E3 10 01 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 13 01 20 14 03 05 08 08 04 01 F7 00 23 01 09 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   0F 05 00 E2 ED 10 01 00 13 01 20 14 03 06 02 08 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   09 0F 05 00 E2 E3 10 01 00 13 01 20 14 03 05 08 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   08 04 01 F8 00 23 01 09 0F 05 00 E2 ED 10 01 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   13 01 20 14 03 06 02 08 09 0F 05 00 E2 E3 10 01 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 13 01 20 14 03 05 08 08 06 01 F9 00 23 01 09 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   0F 05 00 E2 E3 10 01 00 13 01 20 14 03 05 08 08 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   09 0F 05 00 E2 ED 10 01 00 13 01 20 14 03 06 02 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   08 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) This is a DVBAPI_AOT_CA_PMT packet with size 177 => lets process it!
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Received DVBAPI_AOT_CA_PMT object on socket 13:
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Received CA PMT list management 3 for program 4331 (pmt pid: 0000 adapter: 0 demux: 0 camask: 1)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found MPEG-2 video stream (type: 02 pid: 01F6)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 ecmpid 0 CAID: 0500 ECM_PID: 02ED PROVID: 060200 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 ecmpid 1 CAID: 0500 ECM_PID: 02E3 PROVID: 050800 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found MPEG-2 audio stream (type: 04 pid: 01F7)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02ED PROVID: 060200 (Same as ECMPID 0)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02E3 PROVID: 050800 (Same as ECMPID 1)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found MPEG-2 audio stream (type: 04 pid: 01F8)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02ED PROVID: 060200 (Same as ECMPID 0)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02E3 PROVID: 050800 (Same as ECMPID 1)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found MPEG-2 PES private data stream (type: 06 pid: 01F9)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02E3 PROVID: 050800 (Same as ECMPID 1)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found CA descriptor (tag: 09 length: 0F)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 02ED PROVID: 060200 (Same as ECMPID 0)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found 2 ECM pids and 4 STREAM pids in CA PMT
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 try to start new filter for caid: 0001, provid: 000001, pid: 0000
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   40 3C 6F 2B 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   04 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 Filter 1 started successfully (caid 0001 provid 000001 pid 0000)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 started descrambling for program 4331 (SRF 1 HD) (fd: 13)
2019/11/15 18:28:30 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050810
2019/11/15 18:28:30 266B55F4 c      (chk) no match, 0500@060200 rejected by reader 'srg_v5' filters
2019/11/15 18:28:30 266B55F4 c      (chk) r-filter reader srg_v5
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 ignore ecmpid 0 0500@060200:02ED:10000 (no matching reader)
2019/11/15 18:28:30 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) 0500@050800 allowed by reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) 0500@050800 allowed by reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) 0500@050800 allowed by reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 prio ecmpid 1 0500@050800:02E3:10000 weight: 1 (1 readers)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found in channel cache: 0500@050800/08E2/4331/00:(null)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 prio ecmpid 1 0500@050800:02E3 weight: 2 (found caid/provid/srvid in cache)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 found channel in cache and matching prio -> start descrambling ecmpid 1 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 sorting the ecmpids took 0 ms
2019/11/15 18:28:30 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:28:30 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c      (chk) 0500@050800 allowed by reader 'srg_v5' filter 0500@050800
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 trying to descramble PID 1 CAID 0500 PROVID 050800 ECMPID 02E3 ANY CHID PMTPID 0000 VPID 01F6
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 try to start new filter for caid: 0500, provid: 050800, pid: 02E3
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   40 3C 6F 2B 00 00 01 02 E3 80 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 F0 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 0B B8 00 00 00 
2019/11/15 18:28:30 266B55F4 c   (dvbapi)   04 
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 Filter 2 started successfully (caid 0500 provid 050800 pid 02E3)
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Processing socketdata completed after 1 packets with 0 bytes left unprocessed
2019/11/15 18:28:30 266B55F4 c   (dvbapi) Demuxer 0 has 2 ecmpids, 4 streampids, 1 ecmfilters and 0 of max 63 emmfilters
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 try to start new filter for caid: 0001, provid: 000001, pid: 0001
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   40 3C 6F 2B 00 00 02 00 01 01 00 00 00 00 00 00 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   04 
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 Filter 3 started successfully (caid 0001 provid 000001 pid 0001)
2019/11/15 18:28:50 266B55F4 c   (dvbapi) New events occurred on 1 of 2 handlers after 20099 ms inactivity
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Now handling fd 13 that reported event 1
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Try reading 4 bytes from connection fd 13
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Got packetdata (msgid size: 0, clientprotocol: 2)
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   FF FF 00 00 00 02 01 B0 1B FF FF ED 00 00 09 04 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   18 50 E0 80 09 04 18 01 E0 81 09 04 18 62 E0 82 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   FE D4 F2 9C 
2019/11/15 18:28:50 266B55F4 c   (dvbapi) This is a DVBAPI_FILTER_DATA packet with size 36 => lets process it!
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 filter3[0] = 01, filter mask[0] = FF, flt&mask = 01 , buffer[0] = 01, buffer[0] & mask = 01
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 filter 3 fetched CAT data (length = 0x01E):
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   01 B0 1B FF FF ED 00 00 09 04 18 50 E0 80 09 04 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   18 01 E0 81 09 04 18 62 E0 82 FE D4 F2 9C 
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 stop filter 3 try 1 (fd: 65535 api: 0, caid: 0001, provid: 000001, emmpid: 0001)
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   00 00 6F 2A 00 00 02 00 01 
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Added new emmpid 0 CAID: 1850 EMM_PID: 0080 PROVID: 000000    TYPE :UNIQUE:SHARED:GLOBAL:
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Added new emmpid 1 CAID: 1801 EMM_PID: 0081 PROVID: 000000    TYPE :UNIQUE:SHARED:GLOBAL:
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Added new emmpid 2 CAID: 1862 EMM_PID: 0082 PROVID: 000000    TYPE :UNIQUE:SHARED:GLOBAL:
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Processing socketdata completed after 1 packets with 0 bytes left unprocessed
2019/11/15 18:28:50 266B55F4 c   (dvbapi) New events occurred on 1 of 2 handlers after 0 ms inactivity
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Now handling fd 13 that reported event 1
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Try reading 4 bytes from connection fd 13
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Got packetdata (msgid size: 0, clientprotocol: 2)
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   FF FF 00 00 00 02 01 B0 1B FF FF ED 00 00 09 04 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   18 50 E0 80 09 04 18 01 E0 81 09 04 18 62 E0 82 
2019/11/15 18:28:50 266B55F4 c   (dvbapi)   FE D4 F2 9C 
2019/11/15 18:28:50 266B55F4 c   (dvbapi) This is a DVBAPI_FILTER_DATA packet with size 36 => lets process it!
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Demuxer 0 filter3[0] = 01, filter mask[0] = FF, flt&mask = 01 , buffer[0] = 01, buffer[0] & mask = 01
2019/11/15 18:28:50 266B55F4 c   (dvbapi) Processing socketdata completed after 1 packets with 0 bytes left unprocessed
2019/11/15 18:29:20 266B55F4 c   (dvbapi) Demuxer 0 matching reader srg_v5 against available emmpids -> START!
2019/11/15 18:29:20 266B55F4 c   (dvbapi) Demuxer 0 matching reader srg_v5 against available emmpids -> DONE!
2019/11/15 18:29:20 266B55F4 c   (dvbapi) Demuxer 0 handles 0 emm filters
2019/11/15 18:29:31 266B55F4 c   (dvbapi) New events occurred on 1 of 2 handlers after 40909 ms inactivity
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Now handling fd 13 that reported event 1
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Try reading 4 bytes from connection fd 13
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Got packetdata (msgid size: 0, clientprotocol: 2)
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   FF FF 00 00 00 01 81 70 27 00 90 03 05 08 08 E2 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   03 4F 6F 01 EA 10 84 36 3E 87 C0 DA 7F E5 8C 85 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   70 FB 76 46 02 00 F0 08 B7 88 5D CE 7E B3 DE 34 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) This is a DVBAPI_FILTER_DATA packet with size 48 => lets process it!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 filter2[0] = 80, filter mask[0] = F0, flt&mask = 80 , buffer[0] = 81, buffer[0] & mask = 80
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 filter 2 fetched ECM data (length = 0x02A):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   81 70 27 00 90 03 05 08 08 E2 03 4F 6F 01 EA 10 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   84 36 3E 87 C0 DA 7F E5 8C 85 70 FB 76 46 02 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   F0 08 B7 88 5D CE 7E B3 DE 34 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ECMTYPE 81 CAID 0500 PROVID 050800 ECMPID 02E3 FAKECHID 08E2 (unique part in ecm)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 Filter 2 set ecmtable to EVEN (CAID 0500 PROVID 050800 FD 65535)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 Filter 2 set chid to ANY CHID on fd 65535
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 3C 6F 2B 00 00 01 02 E3 80 00 00 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 FF 00 00 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   04 
2019/11/15 18:29:31 266B55F4 c      (ecm) get cw for ecm:
2019/11/15 18:29:31 266B55F4 c      (ecm)   81 70 27 00 90 03 05 08 08 E2 03 4F 6F 01 EA 10 
2019/11/15 18:29:31 266B55F4 c      (ecm)   84 36 3E 87 C0 DA 7F E5 8C 85 70 FB 76 46 02 00 
2019/11/15 18:29:31 266B55F4 c      (ecm)   F0 08 B7 88 5D CE 7E B3 DE 34 
2019/11/15 18:29:31 266B55F4 c      (chk) caid 0500 not found in caidlist reader cc
2019/11/15 18:29:31 266B55F4 c      (chk) trying reader 'srg_v5' filter 0500@050800
2019/11/15 18:29:31 266B55F4 c      (chk) 0500@050800 allowed by reader 'srg_v5' filter 0500@050800
2019/11/15 18:29:31 266B55F4 c      (ecm) [GET_CW] wait_time 0 caid 0500 prov 050800 srvid 4331 rc 100 cacheex cl mode 0 ex1rdr 0
2019/11/15 18:29:31 266B55F4 c      (ecm) request_cw stage=3 to reader srg_v5 ecm hash=20C4054F584AAE985F77FED90A2C38BF
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 request controlword for ecm 0500@050800/08E2/4331/2A:20C4054F584AAE985F77FED90A2C38BF
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Processing socketdata completed after 1 packets with 0 bytes left unprocessed
2019/11/15 18:29:31 58A72065 r   (reader) srg_v5 [viaccess] TRACE: SW1: 90
2019/11/15 18:29:31 58A72065 r   (reader) srg_v5 [viaccess] TRACE: SW2: 00
2019/11/15 18:29:31 58A72065 r   (reader) srg_v5 [viaccess] TRACE: SW1: 90
2019/11/15 18:29:31 58A72065 r   (reader) srg_v5 [viaccess] TRACE: SW2: 00
2019/11/15 18:29:31 58A72065 r   (reader) srg_v5 [viaccess] TRACE: ecm answer for ecm hash 20C4054F584AAE985F77FED90A2C38BF rc=0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 control word received for PID 1 CAID 0500 PROVID 050800 ECMPID 02E3 CHID 08E2 VPID 01F6
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 requested controlword for ecm 20C4054F584AAE985F77FED90A2C38BF on fd 65535
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 descrambling PID 1 CAID 0500 PROVID 050800 ECMPID 02E3 CHID 8E2 VPID 01F6
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 PID: 1 CAID: 0500 ECMPID: 02E3 is using index 0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Added new streampid 01F6 with index 0 to ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 disable stream 1 pid=0x01f6 index=-1 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F6 FF FF FF FF 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 enable stream 1 pid=0x01f6 by index=0 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F6 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Added new streampid 01F7 with index 0 to ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 disable stream 2 pid=0x01f7 index=-1 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F7 FF FF FF FF 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 enable stream 2 pid=0x01f7 by index=0 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F7 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Added new streampid 01F8 with index 0 to ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 disable stream 3 pid=0x01f8 index=-1 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F8 FF FF FF FF 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 enable stream 3 pid=0x01f8 by index=0 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F8 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Added new streampid 01F9 with index 0 to ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 disable stream 4 pid=0x01f9 index=-1 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F9 FF FF FF FF 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 enable stream 4 pid=0x01f9 by index=0 on ca0
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 08 6F 87 00 00 00 01 F9 00 00 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F6 -> write odd part of cw!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 writing odd part (280A9FD163769C75) of controlword, replacing expired (0000000000000000)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 write cw0 index: 0 (ca0)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 10 6F 86 00 00 00 00 00 00 00 00 00 28 0A 9F 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   D1 63 76 9C 75 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F7 -> skip, odd part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F8 -> skip, odd part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F9 -> skip, odd part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F6 -> write even part of cw!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 writing even part (3BA415F43D93EEBE) of controlword, replacing expired (0000000000000000)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 write cw1 index: 0 (ca0)
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   40 10 6F 86 00 00 00 00 00 00 00 00 01 3B A4 15 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   F4 3D 93 EE BE 
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F7 -> skip, even part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F8 -> skip, even part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Demuxer 0 ca0 is using index 0 for streampid 01F9 -> skip, even part of cw already written!
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Using 1 of 64 total descramblers
2019/11/15 18:29:31 266B55F4 c   (dvbapi) Sending packet to dvbapi client (fd=13):
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   FF FF 00 03 00 43 31 05 00 02 E3 00 05 08 00 00 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   00 00 BC 08 76 69 61 63 63 65 73 73 06 73 72 67 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   5F 76 35 05 6C 6F 63 61 6C 06 73 6D 61 72 67 6F 
2019/11/15 18:29:31 266B55F4 c   (dvbapi)   00 
2019/11/15 18:29:31 266B55F4 c      (ecm) reel (0500@050800/08E2/4331/2A:20C4054F584AAE985F77FED90A2C38BF): found (188 ms) by srg_v5 - SRF 1 HD
2019/11/15 18:29:31 266B55F4 c      (ecm) cw:
2019/11/15 18:29:31 266B55F4 c      (ecm)   28 0A 9F D1 63 76 9C 75 3B A4 15 F4 3D 93 EE BE 
2019/11/15 18:29:40 266B55F4 c      (ecm) reel (0500@050800/08E2/4331/2A:2F37704339810EA9EB47EE8BF68544A9): found (188 ms) by srg_v5 - SRF 1 HD
2019/11/15 18:29:50 266B55F4 c      (ecm) reel (0500@050800/08E2/4331/2A:1E99B4683B3C33DB315FFFB4C349AEE8): found (188 ms) by srg_v5 - SRF 1 HD

At 18:29:31 the reception starts after 40 s inactivity on dvbapi. Some other 20 s inactivity is before. Obviously oscam does not get the needed info. Any hints?

REELcoder commented 4 years ago

Is definitely not related to dvbapi but to satip-plugin:

https://github.com/rofafor/vdr-plugin-satip/issues/58