Open lars18th opened 5 years ago
Hi,
can you find a repro that shows the same behaviour with 2 channels from different transponders? Thanks
Hi @catalinii ,
Doing more debug I have a new question: The DVBAPI socket is running synch or asynch? I see troubles (discontinuity CC) every time the socket of Oscam is used.
Please @catalinii try this change: https://github.com/catalinii/minisatip/pull/564
Hi @catalinii ,
If you want to try it for yourself, then do this:
./minisatip -O ... -l general,ca,dvbapi | grep 'PID Continuity error\|filter' > check.log &
tail -f check.log | grep -A 1 -B 1 -C 1 Continuity
Then connect some client to your minisatip server and start to do zapping over encrypted channels. Then see that sometimes the CC error found when you change the channel. And it only appears when you do the change. However, not all the times it appears.
I'm not sure if the problem is because a lock semaphore or because another cause. But it's a real problem. Any idea?
The only thing I noticed is continuity error while a channel is not decrypted. Is this issue different?
The only thing I noticed is continuity error while a channel is not decrypted. Is this issue different?
Yes, I think is a different issue, but I'll check it.
hello,
i do have an issue with some channels f.ex. DAZN 1/2 HD - eurosprot 1/2HD,... were the streams stop and i got lots of pixel error on the screen - i did turned on logging and it looks like everytime 'PID Continuity error ' is shown my tv freezes.
[29/09 20:24:42.463 AD0]: found CW: 1 for �DAZN� �1 Bar� �HD� PMT 4, pid 102, master 4, 273 ms ago, parity 0: 78 C1 9A D3 2F 0A F4 2D
[29/09 20:24:42.504 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:42.716 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 17000 dB -> 11140, BER: 0, err 0
[29/09 20:24:42.716 signal]: BW 2480KB/s, Total BW: 734 MB, ns/read 859, r: 82, w: 1965 fw: 0, tt: 70 ms
[29/09 20:24:43.028 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:43.052 AD0]: Found pid 1791 dec 0 enc 21 pmt 4 first pid 1791, grace time 0 ms
[29/09 20:24:43.052 AD0]: Disabling CW 1, parity 0 for PMT 4 master 4, created 863 ms ago: 78 C1
[29/09 20:24:43.094 AD0]: update_cw: pmt 4, parity 0, CW -1
[29/09 20:24:43.094 AD0]: found CW: -1 for �DAZN� �1 Bar� �HD� PMT 4, pid 102, master 4, 0 ms ago, parity 0: not found
[29/09 20:24:43.136 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 0, previous parity -1, demux = 0, filter = 0, len = 159 [80 70 9C 00]
[29/09 20:24:43.240 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:43.552 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:43.764 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:44.076 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:44.149 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 4, Actual CC: 7, CC Before 3
[29/09 20:24:44.191 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 8, Actual CC: 6, CC Before 7
[29/09 20:24:44.288 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:44.288 signal]: BW 1741KB/s, Total BW: 736 MB, ns/read 292, r: 83, w: 1388 fw: 0, tt: 24 ms
[29/09 20:24:44.360 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 0, previous parity -1, demux = 0, filter = 0, len = 159 [80 70 9C 00]
[29/09 20:24:44.600 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:44.816 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:45.128 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:45.225 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 7, Actual CC: 8, CC Before 6
[29/09 20:24:45.344 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:45.478 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 9, Actual CC: 4, CC Before 8
[29/09 20:24:45.605 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 0, previous parity -1, demux = 0, filter = 0, len = 159 [80 70 9C 00]
[29/09 20:24:45.656 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:45.872 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:45.872 signal]: BW 331KB/s, Total BW: 736 MB, ns/read 207, r: 90, w: 308 fw: 0, tt: 18 ms
[29/09 20:24:45.890 main]: read RTSP (from handle 17 sock 13, len: 86, sid 1):
[29/09 20:24:45.890 main]: reply -> 17 (192.168.249.22:19971) CL:0 [sock_id 13]:
[29/09 20:24:46.153 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 5, Actual CC: 7, CC Before 4
[29/09 20:24:46.184 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:46.396 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:46.533 AD0]: Found pid 1791 dec 0 enc 3 pmt 4 first pid 1791, grace time 0 ms
[29/09 20:24:46.617 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 0, previous parity -1, demux = 0, filter = 0, len = 159 [80 70 9C 00]
[29/09 20:24:46.660 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 8, Actual CC: 5, CC Before 7
[29/09 20:24:46.708 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:46.913 AD0]: Found pid 1791 dec 0 enc 3 pmt 4 first pid 1791, grace time 0 ms
[29/09 20:24:46.920 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:46.997 AD0]: Found pid 1791 dec 0 enc 3 pmt 4 first pid 1791, grace time 0 ms
[29/09 20:24:47.039 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 6, Actual CC: 8, CC Before 5
[29/09 20:24:47.232 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:47.335 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 9, Actual CC: 3, CC Before 8
[29/09 20:24:47.444 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:47.444 signal]: BW 319KB/s, Total BW: 736 MB, ns/read 212, r: 86, w: 296 fw: 0, tt: 18 ms
[29/09 20:24:47.756 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:47.862 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 0, previous parity -1, demux = 0, filter = 0, len = 159 [80 70 9C 00]
[29/09 20:24:47.968 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 17000 dB -> 11140, BER: 0, err 0
[29/09 20:24:48.015 main]: Mutex init 0x55c3fefc83a8
[29/09 20:24:48.015 main]: sockets_add: handle 11 (type 1) returning socket sock 9 [192.168.252.252:64765] read: 0x55c3fd2821c8
[29/09 20:24:48.016 main]: read HTTP from 11 sid: -1:
[29/09 20:24:48.016 main]: reply -> 11 (192.168.252.252:64765) CL:15127 [sock_id 9]:
[29/09 20:24:48.021 main]: select_and_execute[9]: Close on socket 11 (sid:-1) from 192.168.252.252:64765 - type http errno 0
[29/09 20:24:48.021 main]: minisatip.c:1475 get_sid returns NULL for s_id = -1
[29/09 20:24:48.021 main]: Requested stream close -1 timeout -1 type -1
[29/09 20:24:48.021 main]: closing stream -1
[29/09 20:24:48.021 main]: sockets_del: sock 9 -> handle 11, sid -1, overflow bytes 0, allocated 0, used 0, unsend packets 0
[29/09 20:24:48.021 main]: sockets_del: 9 Last open socket is at index 43 current_handle 11
[29/09 20:24:48.021 main]: Destroying mutex 0x55c3fefc83a8
[29/09 20:24:48.021 main]: Delete socket 9 done: sid -1
[29/09 20:24:48.280 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:48.492 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:48.495 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 4, Actual CC: 9, CC Before 3
[29/09 20:24:48.804 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15700 dB -> 10288, BER: 0, err 0
[29/09 20:24:48.833 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: A, Actual CC: 2, CC Before 9
[29/09 20:24:48.875 AD0]: dvbapi: sending ECM key 0 for pid 1A55 (6741), current ecm_parity = 1, previous parity -1, demux = 0, filter = 0, len = 159 [81 70 9C 00]
[29/09 20:24:48.875 AD0]: Expiring CW 0, PMT 4, parity 1 created 13694 ms ago, CW: DF 8E
[29/09 20:24:48.875 main]: dvbapi read from socket 15 the following data (65 bytes), pos = 0, op 403C6F2B, key 0
[29/09 20:24:48.875 main]: dvbapi set filter for pid 1A55 (6741), key 0, demux 0, filter 0
[29/09 20:24:48.875 main]: dvbapi: filter for pid 6741 and key 0 already exists, fid 9
[29/09 20:24:49.020 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:49.020 signal]: BW 339KB/s, Total BW: 737 MB, ns/read 229, r: 95, w: 301 fw: 0, tt: 21 ms
[29/09 20:24:49.153 main]: dvbapi read from socket 15 the following data (21 bytes), pos = 0, op 40106F86, key 0
[29/09 20:24:49.153 main]: dvbapi: received DVBAPI_CA_SET_DESCR, key 0 parity 1, index 0, CW NOK: 03 9E 85 70 98 3A 6C 30
[29/09 20:24:49.153 main]: got CW for PMT 4, master 4, algo 0, parity 1: 03 9E 85 70 98 3A 6C 30
[29/09 20:24:49.153 main]: CW 0 for �DAZN� �1 Bar� �HD� PMT 4, master 4, pid 102, expiry in 25000 ms, algo 0, parity 1: 03 9E 85 70 98 3A 6C 30
[29/09 20:24:49.153 main]: dvbapi read from socket 15 the following data (68 bytes), pos = 0, op FFFF0003, key 0
[29/09 20:24:49.153 main]: dvbapi: ECM_INFO: key 0, SID = 0084, CAID = 098C (videoguard), PID = 6741 (1A55), ProvID = 000000, ECM time = 278 ms, reader = skyde2_main-act, from = svx.holli, protocol = newcamd, hops = 0
[29/09 20:24:49.170 AD0]: update_cw: pmt 4, parity 0, CW -1
[29/09 20:24:49.170 AD0]: found CW: -1 for �DAZN� �1 Bar� �HD� PMT 4, pid 102, master 4, 0 ms ago, parity 0: not found
[29/09 20:24:49.212 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 3, Actual CC: 0, CC Before 2
[29/09 20:24:49.336 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15700 dB -> 10288, BER: 0, err 0
[29/09 20:24:49.465 AD0]: Parity change for �DAZN� �1 Bar� �HD� PMT 4, new active parity 1 pid 1791 [47 06 FF D3], last_parity_change 528523
[29/09 20:24:49.465 AD0]: update_cw: pmt 4, parity 1, CW -1
[29/09 20:24:49.465 AD0]: candidate CW 0, prio 0, time 312 ms ago, expiry in 24688 s, parity 1, pmt 4, change 1
[29/09 20:24:49.465 AD0]: found CW: 0 for �DAZN� �1 Bar� �HD� PMT 4, pid 102, master 4, 312 ms ago, parity 1: 03 9E 85 70 98 3A 6C 30
[29/09 20:24:49.466 AD0]: PID Continuity error (adapter 0): pid: 1791, Expected CC: 2, Actual CC: 3, CC Before 1
[29/09 20:24:49.466 AD0]: PID Continuity error (adapter 0): pid: 1795, Expected CC: C, Actual CC: 5, CC Before B
[29/09 20:24:49.548 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:49.868 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15700 dB -> 10288, BER: 0, err 0
[29/09 20:24:50.084 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:50.396 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:50.608 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 16900 dB -> 11075, BER: 0, err 0
[29/09 20:24:50.608 signal]: BW 2273KB/s, Total BW: 739 MB, ns/read 684, r: 93, w: 1799 fw: 0, tt: 63 ms
[29/09 20:24:50.920 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0
[29/09 20:24:50.923 AD0]: Found pid 1791 dec 11 enc 0 pmt 4 first pid 1791, grace time 0 ms
Message repeated 1 times
any idea?
thanks holli
[29/09 20:24:42.463 AD0]: found CW: 1 for �DAZN� �1 Bar� �HD� PMT 4, pid 102, master 4, 273 ms ago, parity 0: 78 C1 9A D3 2F 0A F4 2D [29/09 20:24:42.504 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0 [29/09 20:24:42.716 signal]: get_signal_new adapter 1: status 31, strength -210 dBm -> 65397, snr 17000 dB -> 11140, BER: 0, err 0 [29/09 20:24:42.716 signal]: BW 2480KB/s, Total BW: 734 MB, ns/read 859, r: 82, w: 1965 fw: 0, tt: 70 ms [29/09 20:24:43.028 signal]: get_signal_new adapter 0: status 31, strength -200 dBm -> 65403, snr 15600 dB -> 10223, BER: 0, err 0 [29/09 20:24:43.052 AD0]: Found pid 1791 dec 0 enc 21 pmt 4 first pid 1791, grace time 0 ms [29/09 20:24:43.052 AD0]: Disabling CW 1, parity 0 for PMT 4 master 4, created 863 ms ago: 78 C1 [29/09 20:24:43.094 AD0]: update_cw: pmt 4, parity 0, CW -1
Disabling CW 1 indicates that the CW received is not correct for that channel. As a result the image is not decrypted. A CC error is not big enough to be visible on the screen.
Hi @catalinii ,
I close this issue as the PR #639 has fixed the problem. It seems that the cause is the SAT>IP server that receives a delpids=
and addpids=
of the same pid in the same command. And for this reason a small CC error is generated. So the problem was observed only with the satipc
adapters.
Regards.
Hi @catalinii ,
I reopen again this issue because the problem (unfortunately) is not fixed.
I see it more times when playing 2 services from the same transponder. And I detected that the problem appears every time an EXPIRING CW is detected.
See this small part of the LOG:
[21/11 10:55:39.815 AD1]: Expiring CW 0, PMT 4, parity 0 created 17908 ms ago, CW: 57 2C
[21/11 10:55:39.815 main]: dvbapi read from socket 10 the following data (65 bytes), pos = 0, op 403C6F2B, key 1
[21/11 10:55:39.815 main]: dvbapi set filter for pid 0642 (1602), key 1, demux 1, filter 0
[21/11 10:55:39.815 main]: dvbapi: filter for pid 1602 and key 1 already exists, fid 16
[21/11 10:55:40.077 AD1]: PID Continuity error (adapter 1): pid: 361, Expected CC: 5, Actual CC: D, CC Before 4
[21/11 10:55:40.077 AD1]: PID Continuity error (adapter 1): pid: 362, Expected CC: 1, Actual CC: 4, CC Before 0
[21/11 10:55:40.077 AD1]: PID Continuity error (adapter 1): pid: 2143, Expected CC: 4, Actual CC: 5, CC Before 3
And now I'm completly sure of it: if no EXPIRE CW appears, then I don't see any CC error. And every time an EXPIRE CW appears in the log, then some CC errors appears. So the problem is correlated with the expiring of the codeword.
Any idea to fix this problem? Thank you!
Hi @catalinii ,
After more tests, I discovered that the problem is not the expiring of the cw (even it's related because the processing of it). The problem is the overhead in the stream processing. When using two services from the same transponder the bitsteam is increased. And the processing too. Then the small DVB buffer using the satipc function is the cause of the CC errors, as it forgets some input packets.
However, I have the problem that I can't increase the DVB buffer. When using a Panasonic TV as the SAT>IP client, it requires to send packets at regular intervals and with small delay (aka, minimal jitter). So, for this reason I'm using -H 1:5 -b 18048:54144 -B 750
. With these values the play goes right. But if I increase the DVB buffer to reduce the incoming CC errors, then some glitches appear in the play.
Any ideas to overcome this problem?
Hi @catalinii ,
This PR #649 partially improves the problem. However, it's not fully fixed. In any case, please merge it.
Regards.
@lars18th The only issue I saw is that while a channel is not decrypted, CC errors are being generated. Last time I looked at it some packets would come unencrypted but it is possible to be a bug.
That would explain why do you see the messages after expiring the CW. Do you think is the same issue I mention about ?
@lars18th The only issue I saw is that while a channel is not decrypted, CC errors are being generated. Last time I looked at it some packets would come unencrypted but it is possible to be a bug.
That would explain why do you see the messages after expiring the CW. Do you think is the same issue I mention about ?
Hi @catalinii ,
After my research, regarding CC errors I found different causes:
addpids
and delpids
are sended.I feel that's the full list of current causes of the CC errors. I hope it helps. Regards.
@lars18th The only issue I saw is that while a channel is not decrypted, CC errors are being generated. Last time I looked at it some packets would come unencrypted but it is possible to be a bug.
That would explain why do you see the messages after expiring the CW. Do you think is the same issue I mention about ?
Hi @catalinii ,
Your assumption about CC errors generated by a not decrypted packets are IMPOSSIBLE, as I'm using every time the -E
parameter. So all unencrypted packets are passed. Futhermore the CC counter isn't encrypted and no encrypted packets are discarded in the input. So the problem is in another part of the source. I feel that the dvbapi implementation is discarding some input packets at some point.
Hi @catalinii ,
I feel I have found the cause of the problem. First my assumption about this issue:
To check this I commented this line, and even if it generates error messages trying to send a closed ECM stream, it resolves the problem (so it's only a proof-of-concept): https://github.com/catalinii/minisatip/blob/70d0f9f7da04db41819753f19b440a9218fbf84d/src/dvbapi.c#L262
So, the problem seems to be reduced to this: The processing of the DMX_STOP will remove the ECM pid. However, this will be only necessary when changing to another program. So if we continue playing the same program, then instead of removing the pid from the list and add it afterwards, it's preferable to delete the filter but not the pid from the list.
What you think?
Hi @catalinii ,
I confirm that the source of the problem is the SAT>IP server: when the pid list is updated some CC errors appears.
So, I created a draft PR to resolve this problem: #668 .
It works, but to complete it I need your feedback. What you prefer?
Please, comment about it. I really want to fix this problem! Thank you!
Is this still an issue?
Is this still an issue?
Yes in some circunstances. For example, in some devices calling to the pid filtering sys call function could generate some glitches. In these cases the stream will suffer for some CC errros. And this is true if you drive a physical tuner from minisatip, but it's also true if you drive a remote SAT>IP server from minisatip. Therefore, I recommend to leave this issue open. Two reasons: first to document the issue (without any direct fix), and second to provide workarounds. For example, I'm thinking on some enhancement for selecting adapters based on some circunstances (number of already used pids, bandwith, etc.). And in this case, then the open-close of pids could be improved (with some delay to reduce fast "close-reopen" calls).
Regards.
Which devices experience this? I'd rather just document it than introduce complicated logic to work around it.
Which devices experience this? I'd rather just document it than introduce complicated logic to work around it.
It depends on the manufacturer. I detected that SAT>IP devices based on ALi has this problem. Also some Mirage STBs. And you can add some Enigma2 boxes too. A lot of them exist, so it's difficult to document. An remember that sometimes the glitchs appear adding pids, on other platforms it's deleting pids, on some it's adding and deleting, and in others it's based on the used bandwith. So I don't recommend to do anything special, except to recommend to purchase good and reliable SAT>IP servers.
Regards.
Hi @catalinii ,
I observed that when some timeout appears in the Oscam server, then if a "pid deleting" function is executed inside minisatip, then a PID Continuity error is generated!
See these logs:
The Signal is clean, but every time the pid table is dumped, almost some packet is lost.
Please, can you check it? Thank you!