PID not found CI+ CAM after ~15 min of playback

[Delitants]

Channel stops being decoded by CI+ cam and minisatip throws error that PID, responsible for CA is not found, which is not true. Gets resolved by minisatip full restart.

http://192.168.10.227:8082/?fe=-1&src=1&freq=10727&pol=H&msys=DVBS2&sr=30000&pids=0,1,17,16,18,6040,6041,6042,6043,6044,6045,6046

[29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 18 for fd 12 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6040 for fd 21 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6041 for fd 22 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6042 for fd 23 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6043 for fd 24 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6044 for fd 25 [0 ms] [29/12 00:00:52.883 main]: AD 2 [dvr 2 0], setting filter on PID 6045 for fd 26 [0 ms] [29/12 00:00:52.884 main]: AD 2 [dvr 2 0], setting filter on PID 6046 for fd 27 [0 ms] [29/12 00:00:52.884 main]: Reply (handle 11) [192.168.10.227:27530] content_len:0, sock 11 [29/12 00:00:52.923 AD2]: Sending PMT 2 to all CAs: ad_ca_mask 1, pmt_ca_mask 0, disabled_ca_mask 0 [29/12 00:00:52.923 AD2]: CAID 1856 and mask FFFF matched PMT 2 [29/12 00:00:52.923 AD2]: PMT CA 2 pmt 2 pid 6040 (Museum 4K) ver 5 sid 4604 (4604), enabled_pmts 1, CLM_UPDATE, PMTS to be send 2 -1, pos 0 [29/12 00:00:52.923 AD2]: ca_write_apdu: CA 2, session 7, name EN50221_APP_CA_RESOURCEID, write tag 9F8032, data length 432 [29/12 00:00:52.991 AD2]: cw already exist at position 0: id 0, parity 0, pmt 2, time 1508858 ms ago, expiry in 2091142 ms, CW: AF 5B EE F4 DF C1 90 52, IV: BD 18 24 54 46 F5 4C 65 [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6041 while processing the PAT [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6042 while processing the PAT [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6043 while processing the PAT [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6044 while processing the PAT [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6045 while processing the PAT [29/12 00:00:52.991 AD2]: Found PMT 2 active with pid 6046 while processing the PAT [29/12 00:00:52.991 AD2]: found CW: 0 [not validated] for Museum 4K PMT 2, old cw -1, packets 324, parity 0, pid 6040: id 0, parity 0, pmt 2, time 1508858 ms ago, expiry in 2091142 ms, CW: AF 5B EE F4 > [29/12 00:00:52.991 AD2]: Start streaming for stream sid 1, len 61476 to handle 11 => 192.168.10.227:27530 [29/12 00:00:52.992 AD2]: found CW: -1 [validated] for Museum 4K PMT 2, old cw 0, packets 531, parity 0, pid 6040: not found [29/12 00:00:53.154 signal]: BW 1705 KB/s, DMX 3038 KB/s, Buffered 0 MB, Total BW: 3872 MB, ns/read 3255, r: 23, w: 47 fw: 0, tt: 74 ms [29/12 00:00:54.168 signal]: BW 1719 KB/s, DMX 3173 KB/s, Buffered 0 MB, Total BW: 3873 MB, ns/read 288, r: 25, w: 50 fw: 0, tt: 7 ms [29/12 00:00:55.178 signal]: BW 1729 KB/s, DMX 3193 KB/s, Buffered 0 MB, Total BW: 3875 MB, ns/read 292, r: 25, w: 50 fw: 0, tt: 7 ms [29/12 00:00:56.204 signal]: BW 1724 KB/s, DMX 3180 KB/s, Buffered 0 MB, Total BW: 3877 MB, ns/read 261, r: 25, w: 50 fw: 0, tt: 6 ms [29/12 00:00:57.218 signal]: BW 1657 KB/s, DMX 3060 KB/s, Buffered 0 MB, Total BW: 3879 MB, ns/read 263, r: 24, w: 48 fw: 0, tt: 6 ms [29/12 00:00:58.233 signal]: BW 1722 KB/s, DMX 3182 KB/s, Buffered 0 MB, Total BW: 3880 MB, ns/read 272, r: 25, w: 50 fw: 0, tt: 6 ms [29/12 00:00:59.250 signal]: BW 1728 KB/s, DMX 3189 KB/s, Buffered 0 MB, Total BW: 3882 MB, ns/read 264, r: 25, w: 50 fw: 0, tt: 6 ms [29/12 00:01:00.264 signal]: BW 1651 KB/s, DMX 3048 KB/s, Buffered 0 MB, Total BW: 3884 MB, ns/read 269, r: 24, w: 48 fw: 0, tt: 6 ms [29/12 00:01:01.278 signal]: BW 1730 KB/s, DMX 3192 KB/s, Buffered 0 MB, Total BW: 3885 MB, ns/read 262, r: 25, w: 50 fw: 0, tt: 6 ms [29/12 00:01:02.297 signal]: BW 1721 KB/s, DMX 3176 KB/s, Buffered 0 MB, Total BW: 3887 MB, ns/read 264, r: 25, w: 50 fw: 0, tt: 6 ms [29/12 00:01:03.311 signal]: BW 1660 KB/s, DMX 3065 KB/s, Buffered 0 MB, Total BW: 3889 MB, ns/read 266, r: 24, w: 48 fw: 0, tt: 6 ms [29/12 00:01:03.882 main]: select_and_execute[11]: Close on socket 11 (sid:1) from 192.168.10.227:27530 - type http (3) errno 0 [29/12 00:01:03.882 main]: Requested sid close 1 timeout 30000 type 1, sock 11, handle 11, timeout 0

[Jalle19]

The log doesn't show what happens after 15 minutes. Can you upload a complete log? The "not found" in the log message relates to the CW, not the PID.

[Delitants]

What is the point to upload 1 mile long log if it literally repeats the same I just provided?It says PID 6040 not found, after this message channel stops. Period.On Dec 29, 2022, at 2:47 AM, Sam Stenvall @.***> wrote: The log doesn't show what happens after 15 minutes. Can you upload a complete log? The "not found" in the log message relates to the CW, not the PID.

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you authored the thread.Message ID: @.***>

[Jalle19]

Your log only shows 11 seconds. You can omit the repeating parts, but please upload a more complete log.

[Delitants]

Your log only shows 11 seconds. You can omit the repeating parts, but please upload a more complete log.

Here is full log from the beginning to the end, channel worked literally about 15 min. minisatip2.log

[catalinii]

Can you provide the log with -l ca ?

I see no traffic to the cam after the initialization. Then the CAM switches to parity 1 but no CW for parity 1 is being sent.

[Delitants]

Can you provide the log with -l ca ?

I see no traffic to the cam after the initialization. Then the CAM switches to parity 1 but no CW for parity 1 is being sent.

That is log with CA ExecStart=/root/minisatip-1.2.48/minisatip -I minisatipsecondary -O -x 8082 -y 555 -D 2 -e 2 -c 4:1 -j 2:15-1470 -M :5.0-5.0 -t -Z :0 -l general,ca -F /var/log/minisatip2.log -m 001122334420

[Delitants]

I see no traffic to the cam after the initialization

What's this then? It's in the file attached previously.

[30/12 20:01:45.611 AD2]: RECV ciplus AI msg CA 2, session_num 5, resource_id 9f8021 [30/12 20:01:45.611 AD2]: Application type: 01 [30/12 20:01:45.611 AD2]: Application manufacturer: 0053 [30/12 20:01:45.611 AD2]: Manufacturer code: 0000 [30/12 20:01:45.611 AD2]: CAM Name: CAM 4K tivusat (14) [30/12 20:01:45.611 AD2]: setting CI+ CAM data rate to 96 Mbps [30/12 20:01:45.611 AD2]: ca_write_apdu: CA 2, session 5, name CIPLUS_APP_AI_RESOURCEID, write tag 9F8024, data length 1 [30/12 20:01:45.629 AD2]: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9001, data length 0 [30/12 20:01:45.629 AD2]: RECV ciplus cc msg CAM2, session_num 6, tag 9f9001 len 0 dt_id -1 [30/12 20:01:45.630 AD2]: _elementset stored 30 with len 1 [30/12 20:01:45.630 AD2]: uri version bitmask set to '3' [30/12 20:01:45.630 AD2]: _elementset stored 29 with len 32 [30/12 20:01:45.630 AD2]: _elementset stored 22 with len 32 [30/12 20:01:45.630 AD2]: _elementset stored 5 with len 8 [30/12 20:01:45.630 AD2]: SEND ------------ CC_OPEN_CNF----------- [30/12 20:01:45.630 AD2]: ca_write_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, write tag 9F9002, data length 1 [30/12 20:01:46.791 AD2]: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9003, data length 4 [30/12 20:01:46.791 AD2]: RECV ciplus cc msg CAM2, session_num 6, tag 9f9003 len 4 dt_id 1 [30/12 20:01:46.791 AD2]: req element 22 [30/12 20:01:46.791 AD2]: _elementset stored 22 with len 32 [30/12 20:01:46.791 AD2]: _elementset stored 5 with len 8 [30/12 20:01:46.791 AD2]: SEND ------------ CC_DATA_CNF----------- [30/12 20:01:46.791 AD2]: ca_write_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, write tag 9F9004, data length 37 [30/12 20:01:47.947 AD2]: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9003, data length 27 [30/12 20:01:47.947 AD2]: RECV ciplus cc msg CAM2, session_num 6, tag 9f9003 len 27 dt_id 6 [30/12 20:01:47.947 AD2]: set element(dt_id) 6 dt_len = 8 [30/12 20:01:47.947 AD2]: _elementset stored 6 with len 8 [30/12 20:01:47.947 AD2]: not need to be handled id 6 [30/12 20:01:47.947 AD2]: set element(dt_id) 21 dt_len = 8 [30/12 20:01:47.947 AD2]: _elementset stored 21 with len 8 [30/12 20:01:47.947 AD2]: _elementset stored 20 with len 8 [30/12 20:01:47.947 AD2]: req element 5 [30/12 20:01:47.947 AD2]: req element 20 [30/12 20:01:47.947 AD2]: SEND ------------ CC_DATA_CNF----------- [30/12 20:01:47.947 AD2]: ca_write_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, write tag 9F9004, data length 24 [30/12 20:01:49.103 AD2]: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9005, data length 0 [30/12 20:01:49.103 AD2]: RECV ciplus cc msg CAM2, session_num 6, tag 9f9005 len 0 dt_id -1 [30/12 20:01:49.103 AD2]: SEND ------------ CC_SYNC_CNF----------- [30/12 20:01:49.103 AD2]: ca_write_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, write tag 9F9006, data length 1 30/12 20:01:50.265 AD2: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9007, data length 40 30/12 20:01:50.265 AD2: RECV ciplus cc msg CAM2, session_num 6, tag 9f9007 len 40 dt_id 0 30/12 20:01:50.265 AD2: auth ok! 30/12 20:01:50.265 AD2: serial sac data req: 1 30/12 20:01:50.265 AD2: req element 29 30/12 20:01:50.265 AD2: SEND ------------ CC_SAC_DATA_CNF-----------

30/12 20:01:50.265 AD2: ca_write_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, write tag 9F9008, data length 72 [30/12 20:01:51.436 AD2]: ca_read_apdu: CA 2, session 6, name TS103205_APP_CC_RESOURCEID_THREE, read tag 9F9007, data length 88 [30/12 20:01:51.436 AD2]: RECV ciplus cc msg CAM2, session_num 6, tag 9f9007 len 88 dt_id 0 [30/12 20:01:51.436 AD2]: auth ok! [30/12 20:01:51.436 AD2]: serial sac data req: 2 [30/12 20:01:51.436 AD2]: set element(dt_id) 6 dt_len = 8 [30/12 20:01:51.436 AD2]: _elementset stored 6 with len 8 [30/12 20:01:51.436 AD2]: not need to be handled id 6 [30/12 20:01:51.436 AD2]: set element(dt_id) 12 dt_len = 32 [30/12 20:01:51.436 AD2]: _elementset stored 12 with len 32 [30/12 20:01:51.436 AD2]: not need to be handled id 12 [30/12 20:01:51.436 AD2]: set element(dt_id) 28 dt_len = 1 [30/12 20:01:51.436 AD2]: _elementset stored 28 with len 1 [30/12 20:01:51.436 AD2]: === descrambler_set_key === adapter = CA2 key regiser (0-even, 1-odd) = 0 [30/12 20:01:51.436 AD2]: received from CI+ CAM 2: KEY: A7 15 E8 7D C7 1F C2 76 2F 2B 66 ED 6D 27 93 CE IV: 2E 4D 89 DE 3A DD E6 AB 32 39 53 2F 74 24 A9 C5

[catalinii]

There should be a second "descrambler_set_key"that does not happen.

Can you try '-v ca' then?

[Delitants]

There should be a second "descrambler_set_key"that does not happen.

Can you try '-v ca' then?

minisatip3.log added -v ca

[catalinii]

Did this work with any minisatip version ? if yes, can you identify which version broke it ?

[Delitants]

No, all versions are broken

On Dec 30, 2022, at 11:19 AM, catalinii @.***> wrote:

Did this work with any minisatip version ? if yes, can you identify which version broke it ?

— Reply to this email directly, view it on GitHub https://github.com/catalinii/minisatip/issues/1029#issuecomment-1368093741, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAVUSNVDHICPHO2G5R2BRNTWP5GXZANCNFSM6AAAAAATLTLFHI. You are receiving this because you authored the thread.

[catalinii]

Can u try https://github.com/catalinii/minisatip/releases/tag/v1.1.92 ?

[Delitants]

Can u try https://github.com/catalinii/minisatip/releases/tag/v1.1.92 ?

That's an older version. everything till 1.2.48 acts the same. Ok I will try 1.1.92.

[Delitants]

1.1.92 just failed in the same manner. Worked even less that 15 min. minisatip4.log

UDP: The cause seems in a parallel channel being streamed aside from the same transponder but on another tuner (External Dreambox 920UHD). If I tune DM920 after minisatip, it seems stays on, but if in opposite order, minisatip channel fails in 10-15 min while DM920 remains unaffected. TBS+minisatip and DM920 are sharing the same Unicable II slot and same transponder. DM920 has similar CI+ module installed and runs another channel.

[catalinii]

minisatip4.log is from version 1.2 not 1.1 Can you try to clean the build and compile 1.1 again ?

Do you see the issue if no cAble sharing happens ?

[Delitants]

minisatip4.log is from version 1.2 not 1.1 Can you try to clean the build and compile 1.1 again ?

Do you see the issue if no cAble sharing happens ?

Yes it is exactly that version you suggested me to try. Did you see very first line of the log? [31/12 06:03:52.675 main]: minisatip version 1.1., compiled in Dec 31 2022 06:01:13, with s2api version: 050B

systemctl edit minisatip2 --full ExecStart=/root/minisatip-1.1.92/minisatip

[Jalle19]

Can you make a log where you tune your DM920 first to prevent this issue from happening? I.e. a log where playback doesn't fail after 10 minutes.

[Delitants]

Can you make a log where you tune your DM920 first to prevent this issue from happening? I.e. a log where playback doesn't fail after 10 minutes.

DM920 is not getting tuned to minisatip, it shares same unicable slot with minisait, so there is nothing about dm920 you can see in the log. It’s just a fact that if I tune channel on minisatip before I tune dm920, it does not fail. Yes I can make 30 min long log in this tuning order.

[Jalle19]

Please do

[Jalle19]

Also why do you share the same Unicable slot between two different tuners?

[Delitants]

Also why do you share the same Unicable slot between two different tuners?

Because I need to decode 2 channels using 2 separate CI+ modules and they are on the same transponder. Minisatip has no ability to do that.

[Jalle19]

Should be possible with ddci.conf, if not that sounds like a bug. CI is chosen based on service ID.

[Delitants]

Should be possible with ddci.conf, if not that sounds like a bug. CI is chosen based on service ID.

That’s TBS 6590 dual ci dual tuner. For some reason I can’t separate and assign one channel to one ci and another to another ci. In either case both ci should use the same unicable freq, so it would not matter if that’s another instance of minisatip or external tuner like dm 920. I think the whole problem is shared unicable slot, must be minisatip can’t handle that.

[Jalle19]

Unicable slots are a much lower level than DVB and especially CA systems so I think it's unlikely to be the actual culprit. That's why a log where minisatip doesn't fail after 10 minutes would be good, in case it reveals something else.

[Delitants]

Unicable slots are a much lower level than DVB and especially CA systems so I think it's unlikely to be the actual culprit. That's why a log where minisatip doesn't fail after 10 minutes would be good, in case it reveals something else.

Attached. In this case I've tuned the channel on minisatip first and subsequently a channel on DM920. In this case they are both stay alive. If order is reversed, channel on minisatip fails after 10-15 min and the timeframe is always the same. minisatip5.log

[Jalle19]

So just to clarify, if you use minisatip only and don't involve your DM920 at all, everything works fine?

[Delitants]

So just to clarify, if you use minisatip only and don't involve your DM920 at all, everything works fine?

Correct. Or if I tune dm920 after minisatip started streaming.

[Jalle19]

Are you using SmartWi or something similar to duplicate the card in your two CAMs?

[Delitants]

Are you using SmartWi or something similar to duplicate the card in your two CAMs?

No, that is absolutely different independent cams with own smart cards inside. They have nothing to do with each other except for using the same unicable slot.

[Jalle19]

Does the problem go away if you use a different Unicable slot on the DM920?

[Delitants]

Does the problem go away if you use a different Unicable slot on the DM920?

Yes it does go away

[Delitants]

But I have limited UB channels, and I need to use came UB for minisatip and external tuner, so that's not a solution.

[Jalle19]

I have no idea how Unicable slots could affect your CAM operation, sorry :shrug:

[Delitants]

I have no idea how Unicable slots could affect your CAM operation, sorry 🤷

It affects only minisatip, not the cam. I can run 2 or more external tuners on the same unicable slot just fine without having a hassle of tuning in certain order. Why?

[Delitants]

After more tests it seems problem not in unicable slot but might be in parallel tuning of FTA channel from the same minisatip instance, it's on the same transponder. If I tune CAM channel first, and then FTA channel, it seems stays on.

[Delitants]

Moreover, CAM does not get automatically renewed, have to move it to external tuner every 3 months

[25/01 08:13:26.412 AD2]: CA 2 ======= MMI menu ======= [25/01 08:13:26.412 AD2]: [UI 0] CAM 4K tivusat [25/01 08:13:26.412 AD2]: [UI 1] [25/01 08:13:26.412 AD2]: [UI 2] [25/01 08:13:26.412 AD2]: [UI 3] The tivusat smartcard is not active or [25/01 08:13:26.412 AD2]: [UI 4] it has to be reactivated. [25/01 08:13:26.412 AD2]: [UI 5] Please visit the website www.tivusat.tv, [25/01 08:13:26.412 AD2]: [UI 6] contact the callcenter or follow the [25/01 08:13:26.412 AD2]: [UI 7] procedure described in the instructions. [25/01 08:13:26.412 AD2]: [UI 8] (20)

[catalinii]

Can the cam update be moved to a new issue?

[Delitants]

Can the cam update be moved to a new issue?

I guess it can, unless this is related to current issue. Maybe channel stops decoding because cam does not receive sort of updates from sat?

[catalinii]

If the stream stops to be send to the CAM (because of a tuning issue) then is possible.

Can you upload the log tuning to the FTA channel then wait until decoding stops then stop FTA channel, then encrypted, then stop minisatip

./minisatip -f -l http

[Delitants]

If the stream stops to be send to the CAM (because of a tuning issue) then is possible.

Can you upload the log tuning to the FTA channel then wait until decoding stops then stop FTA channel, then encrypted, then stop minisatip

./minisatip -f -l http

minisatip6.log

[Delitants]

If I don't turn FTA channel on, encrypted stays still.

[catalinii]

I see that the Museum 4K is stopped after the decryption stops. Can you stop the FTA channel and after few seconds to stop Museum 4k ?

And start minisatip before starting the test and upload the entire log

[Delitants]

I see that the Museum 4K is stopped after the decryption stops. Can you stop the FTA channel and after few seconds to stop Museum 4k ?

And start minisatip before starting the test and upload the entire log

I did exact steps you have asked previously. Do you want me to stop it after it failed to decode or not?

[catalinii]

Stop the FTA channel, then stop the Museum 4k

[Delitants]

Stop the FTA channel, then stop the Museum 4k

Before or after Museum has failed on it's own?

[catalinii]

after.. wait 5 seconds, then stop museum too

[Delitants]

Museum failed, disabled FTA, waited 5 sec, disabled Museum, stopped minisatip, sent log. minisatip7.log

[catalinii]

Can you send me also a working log just with museum 4k ?

Better keep it open for at least 25 mins. Generally it fails after 10mins but I want to see 2 key changes.

Btw, do you have other CAM that you can use for Museum 4k ?

[Delitants]

Can you send me also a working log just with museum 4k ?

Better keep it open for at least 25 mins. Generally it fails after 10mins but I want to see 2 key changes.

Btw, do you have other CAM that you can use for Museum 4k ?

No other cam

minisatip8.log

[Delitants]

Here is it failed after I ran Museum alone for 5 min and then turned FTA on and museum failed right after. minisatip10.log