Opened 7 years ago
Last modified 4 years ago
#4365 new defect
OSCam is not respecting oscam.dvbapi when recording was started on sh4/dvbapi boxes (on openpli)
| Reported by: | AbrahaM | Owned by: | theparasol |
|---|---|---|---|
| Priority: | major | Component: | DVBApi |
| Severity: | high | Keywords: | dvbapi oscam.dvbapi failure |
| Cc: | Sensitive: | no |
Description
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.
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
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.
Additional logs, on loglevel 128 will be provided later.
Change History (9)
comment:1 by , 7 years ago
| Owner: | changed from to |
|---|
follow-up: 3 comment:2 by , 7 years ago
comment:3 by , 7 years ago
Replying to pr2:
Hi,
In fact you can avoid this problem by changing the
request_mode = 1
to
request_mode = 0
But even in request_mode = 1 it is 'quite working' it starts first to unscramble from the fastest replying but later on when the P: replies it start to use exclusively the P: defines provider.
But indeed oscam.dvbapi is no longer working as a pure sequential filter like it was before especially in request_more=1
Pr2
As you can see above there IS request_mode = 0 I wouldn't report issue without detailed tests.
Regards,
AbrahaM
comment:4 by , 7 years ago
Mhm, this case made me very interested...
I tried to reproduce precisely the same situation as you described above on my Vu+ Ultimo (VTi 8.2.3 image, well, it's in fact non OpenPLi based system and this is "mipsel" CPU based STB) - both r10619 and the latest r11172 seems to work properly.
After I hit RECORD on the TV remote control, the forbidden SID not appeared, I see deeeep darkness, so OSCam DOES respect oscam.dvbapi entries in this case.
You mentioned in ticket's subject about sh4 and OpenPLi OS...
OK, I'll try do the same test on my sh4/OpenPLi based system. Please give me some time to do that. I'll be back with results later on.
comment:5 by , 7 years ago
On OpenPLi please use PMT Mode 6 this is the advised mode with OpenPLi image.
pmt_mode = 6
comment:6 by , 7 years ago
I checked on sh4 box today morning on r11173, it doesn't matter what pmt_mode was selected, problem was indeed on pmt_mode = 6 and pmt_mode = 0...
But changeset: http://www.streamboard.tv/oscam/changeset/11174 seems to fix the problem.
@AbrahaM, please check r11174 and confirm.
comment:7 by , 7 years ago
Sorry for delay. Issue WAS fixed in r11174 and it seems to be reintroduced somewhere between r11175 - r11213. 11245 Seems to be affected again, but last changeset related with dvbapi is 11214 (with cosmetic log output correction) I'll provide logs as soon as I'll have time to catch exact commit responsible for bug and to do more detailed tests. In this case I have to eliminate "human factor" too, to confirm that issue in 100% again.
comment:8 by , 7 years ago
I have a related issue with my Vu+ Duo that was introduced in changeset r11174.
When I use request_mode = 1 and try to record a scrambled channel while also recording an FTA channel, the scrambled channel freezes and I have to zap or restart OSCam to get back the moving image. The recording itself is okay. I checked and the issue wasn't there in r11173.
With request_mode = 0 everything is completely fine in all recent OSCam versions till today (checked with r11273).
So this issue has something to do with either the behaviour of the ECMpidcount or running variables of the demux object.
It's difficult to debug, cause I've seen no errors with debuglevel=128.
comment:9 by , 4 years ago
This issue is still unsolved. I can't watch one channel and record another at the same time. Picture on watched channel is freezing and stucks till you restart oscam or zap to different channel.
The issue is present on sh4 modchip ADB5800SX. It doesn't exsist on other sh4 boxes. Can anyone invastigate the issue?
Hi,
In fact you can avoid this problem by changing the
request_mode = 1
to
request_mode = 0
But even in request_mode = 1 it is 'quite working' it starts first to unscramble from the fastest replying but later on when the P: replies it start to use exclusively the P: defines provider.
But indeed oscam.dvbapi is no longer working as a pure sequential filter like it was before especially in request_more=1
Pr2