id summary reporter owner description type status priority component severity resolution keywords cc sensitive 4365 OSCam is not respecting oscam.dvbapi when recording was started on sh4/dvbapi boxes (on openpli) AbrahaM theparasol "= Revision all above 10620 including current 11172, last good is 10619, bug is introduced in 10620 = Issue Description OSCam is not respecting oscam.dvbapi when user initiated recording, bug affects sh4/dvbapi boxes which are using openpli. = When the issue occurs after user initiaded recording = How the issue is reproducable To simulate issue just prepare oscam.dvbapi in this way: {{{ I: 0B01:000000:3ABD # ignore SID from 1st proxy I: 1803:000000:3ABD # ignore SID from 2nd proxy I: 0100:000068:3ABD # ignore SID 3ABD from local card (or disable local reader in oscam.server) P: 0B01 # first proxy P: 1803 # second proxy P: 0100:000068 # internal reader I: 0 }}} in oscam.conf ""preferlocalcards = 2"" option is set. r10619 log - no issue - as you see 3ABD is correctly blocked normal user activity / user want's to watch channel {{{ 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 0 CAID: 0100 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 1 CAID: 1813 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 2 CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 3 CAID: 1803 ECM_PID: 0D6D PROVID: 000000 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 4 CAID: 1861 ECM_PID: 0E35 PROVID: 000000 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 5 CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 added new ecmpid 6 CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 3] 2015/11/24 11:02:09 29A00B00 c (dvbapi) Demuxer 0 no suitable readers found that can be used for decoding! 2015/11/24 11:02:12 29A00B00 c (dvbapi) Demuxer 0 no enabled matching ecmpids -> decoding is waiting for matching readers! }}} User is trying to start recording here: {{{ 2015/11/24 11:02:36 29A00B00 c (-) -- Skipped 7 duplicated log lines -- 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 PMT update for decoding of SRVID 3ABD! 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 continue decoding of SRVID 3ABD 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0100 ECM_PID: 0D09 PROVID: 000068 (Same as ECMPID 0) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1813 ECM_PID: 0D09 PROVID: 000068 (Same as ECMPID 1) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 (Same as ECMPID 2) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1803 ECM_PID: 0D6D PROVID: 000000 (Same as ECMPID 3) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1861 ECM_PID: 0E35 PROVID: 000000 (Same as ECMPID 4) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 (Same as ECMPID 5) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 (Same as ECMPID 6) 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 5] 2015/11/24 11:02:36 29A00B00 c (dvbapi) Demuxer 0 no suitable readers found that can be used for decoding! 2015/11/24 11:02:39 29A00B00 c (dvbapi) Demuxer 0 no enabled matching ecmpids -> decoding is waiting for matching readers! }}} User stopped recording here, is only trying to watch channel: {{{ 2015/11/24 11:03:03 29A00B00 c (-) -- Skipped 7 duplicated log lines -- 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 continue decoding of SRVID 3ABD 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0100 ECM_PID: 0D09 PROVID: 000068 (Same as ECMPID 0) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1813 ECM_PID: 0D09 PROVID: 000068 (Same as ECMPID 1) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 (Same as ECMPID 2) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1803 ECM_PID: 0D6D PROVID: 000000 (Same as ECMPID 3) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1861 ECM_PID: 0E35 PROVID: 000000 (Same as ECMPID 4) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 (Same as ECMPID 5) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 skipped stream CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 (Same as ECMPID 6) 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 3] 2015/11/24 11:03:03 29A00B00 c (dvbapi) Demuxer 0 no suitable readers found that can be used for decoding! 2015/11/24 11:03:06 29A00B00 c (dvbapi) Demuxer 0 no enabled matching ecmpids -> decoding is waiting for matching readers! }}} Everything is fine, works as intended, channel is succesfully blocked. [[BR]] [[BR]] [[BR]] r10620 log, where issue was introduced, on first step everything is fine, channel is blocked {{{ 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 0 CAID: 0100 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 1 CAID: 1813 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 2 CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 3 CAID: 1803 ECM_PID: 0D6D PROVID: 000000 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 4 CAID: 1861 ECM_PID: 0E35 PROVID: 000000 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 5 CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 6 CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 3] 2015/11/24 11:14:49 57EFE0 c (dvbapi) Demuxer 0 no suitable readers found that can be used for decoding! 2015/11/24 11:14:51 57EFE0 c (dvbapi) Demuxer 0 no enabled matching ecmpids -> decoding is waiting for matching readers! }}} User is trying to start recording here... and here black magic starts, user is recording channel (and watching it) on SID which is blocked in oscam.dvbapi: {{{ 2015/11/24 11:15:08 57EFE0 c (-) -- Skipped 5 duplicated log lines -- 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 PMT update for decoding of SRVID 3ABD! 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 continue decoding of SRVID 3ABD 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 0 CAID: 0100 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 1 CAID: 1813 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 2 CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 3 CAID: 1803 ECM_PID: 0D6D PROVID: 000000 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 4 CAID: 1861 ECM_PID: 0E35 PROVID: 000000 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 5 CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 6 CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 5] 2015/11/24 11:15:08 57EFE0 c (dvbapi) Demuxer 0 trying to descramble PID 0 CAID 0100 PROVID 000068 ECMPID 0D09 ANY CHID PMTPID 040D VPID 0216 2015/11/24 11:15:09 57EFE0 c (ecm) dvb-api (0100&000068/3ABD/0D09/5C00/013E/64:F40A9997293D086E6E211BAA11A84E07): found (320 ms) by sci0 - TVP 1 HD 2015/11/24 11:15:12 57EFE0 c (ecm) dvb-api (0100&000068/3ABD/0D09/5C00/013E/64:BA82DB1797139C466E211BAA11A84E07): found (567 ms) by sci0 - TVP 1 HD 2015/11/24 11:15:23 57EFE0 c (ecm) dvb-api (0100&000068/3ABD/0D09/5C00/013E/64:BA82DB1797139C469E002BC9BF08864D): found (482 ms) by sci0 - TVP 1 HD }}} User stopped recording here, is only watching channel: {{{ 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 continue decoding of SRVID 3ABD 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 0 CAID: 0100 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 1 CAID: 1813 ECM_PID: 0D09 PROVID: 000068 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 2 CAID: 0B01 ECM_PID: 0C41 PROVID: 000000 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 3 CAID: 1803 ECM_PID: 0D6D PROVID: 000000 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 4 CAID: 1861 ECM_PID: 0E35 PROVID: 000000 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 5 CAID: 0500 ECM_PID: 0DD1 PROVID: 032A00 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 added new ecmpid 6 CAID: 1884 ECM_PID: 0CA5 PROVID: 000000 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 found 7 ECMpids and 10 STREAMpids in PMT 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 receiver wants to demux srvid 3ABD on adapter 0000 camask 0001 index 0000 pmtpid 040D 2015/11/24 11:15:28 57EFE0 c (dvbapi) Demuxer 0 new program number: 3ABD (TVP 1 HD) [pmt_list_management 3] 2015/11/24 11:15:32 57EFE0 c (ecm) dvb-api (0100&000068/3ABD/0D09/5C00/013E/64:CA31332ED0ECDC989E002BC9BF08864D): found (292 ms) by sci0 - TVP 1 HD 2015/11/24 11:15:42 57EFE0 c (ecm) dvb-api (0100&000068/3ABD/0D09/5C00/013E/64:CA31332ED0ECDC989E002BC9BF08864D): found (305 ms) by sci0 - TVP 1 HD }}} [[BR]] It keeps to ""not respect"" oscam.dvbapi until channel zap. After zapping it works fine... until next recording. That issue is having serious impact on OSCam, beceouse it breaks oscam.dvbapi rules, it may lead to decoding from ""unwanted"", unstable CAIDs.[[BR]][[BR]] Additional logs, on loglevel 128 will be provided later." defect closed major DVBApi high fixed dvbapi oscam.dvbapi failure 0