Bug #5036
Descrambling: late key descrambling
0%
Description
I also do not understand why there is such a big jump between keys, but it seems that tvheadend does not recover properly about it, losing the decryption for a while
Files
History
Updated by Pablo R. over 6 years ago
P.S.: I do not know why I have put a question mark at the beginning if they are not used in English. Mornings confuse me totally
Updated by Jaroslav Kysela over 6 years ago
Analysis:
ECM for the new ODD key (a bit late request) 2018-03-25 23:44:48.227 [ TRACE]:descrambler: ECM message 81:30 (section 132, len 142, pid 2185) for service "BEIN LALIGA" stream changed to ODD key at this time (which is unknown, tvh correctly starts buffering) 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: descramble3 3384, even[167] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: descramble3 188, even[121] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: descramble3 376, even[167] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: data append2 564, timestamp 5741960907, odd[167] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: end, odd 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: timestamp 5741960907 thres 5729996959 now 0 (interval 11963ms) odd[167] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: data append 188, timestamp 5741960907, odd[167] 2018-03-25 23:44:51.731 [ TRACE]:descrambler: 0x7fc9440101e0: end, odd received ODD key now 2018-03-25 23:44:51.975 [ DEBUG]:capmt: dvbapi: CA_SET_DESCR adapter 0 par 1 idx 0 cd52cdec6a3819bb 2018-03-25 23:44:51.975 [ TRACE]:descrambler: 0x7fc9440101e0: data append key 0, timestamp 5742211037 2018-03-25 23:44:51.975 [ DEBUG]:descrambler: Obtained CSA keys from capmt-127.0.0.1-9000 for service "BEIN LALIGA" 2018-03-25 23:44:51.975 [ TRACE]:descrambler: Obtained CSA keys 0000000000000000:CD52CDEC6A3819BB pid 0000 from capmt-127.0.0.1-90 00 for service "BEIN LALIGA" 2018-03-25 23:44:51.975 [ DEBUG]:descrambler: info - service='BEIN LALIGA' caid=1810(nagra) provid=000000 ecmtime=3748 hops=2 reader='T' from='192.168.2.197' protocol='cccam_ext'
Here is the problem. TVH appends the key AFTER the queued data, so the data are not flushed (decoded) with this key.
The problem is in this condition:
if (tk->key_timestamp[0] == 0) insert |= 1;
I need to think about this situation more.
Updated by Jaroslav Kysela over 6 years ago
- Subject changed from Descrambling: key interval changed from 12ms to ¿40? and tvheadend cant handle it to Descrambling: late key descrambling
Updated by Pablo R. over 6 years ago
Pablo R. wrote:
I do not know if it is related to the bug in question or not, but when receiving a lot of errors (descrambler: can not decode packets for service "xxx") the following crash occurs.
[...]
I created a new issue for the crash:
http://tvheadend.org/issues/5110
Updated by Pablo R. about 6 years ago
- File logdesc.txt logdesc.txt added
Just tested mostly the same,
2018-10-08 16:30:25.454 [ ERROR]:descrambler: cannot decode packets for service "BEIN LALIGA"
interval from 12058ms to 22744ms...
Updated by Jaroslav Kysela about 6 years ago
Those messages are not handled with the proposed fix (yet), but the picture should be better.
Updated by Jaroslav Kysela about 6 years ago
Also you should increase the descrambler buffer size in the global config (value 20000 or so).
Updated by Pablo R. about 6 years ago
Now that I increased buffer to 20000 from 9000 there are more errors
Is it better to disable buffer? (set it to 0).
Updated by Pablo R. about 6 years ago
It's curious because the number of errors matches the selected buffer. What makes me think that removing the buffer solves it. It's not a crazy idea, is it?
Updated by Jaroslav Kysela about 6 years ago
The buffering must be activated, because your key provider sends the key too late, so TVH must buffer the MPEG-TS packets while the key is not available.
Anyway, show new logs for the updated code.
Updated by Joe User about 6 years ago
I am not sure it will help, but here are a few things I noticed from looking at the first logs (tvh+oscam) and the source code:
1. Keys change MOSTLY at 15sec interval, but sometimes it is ~27sec
2. ts packets also switch mostly at 15sec interval, but sometimes ~27sec
(from 23:44:24.017 to 23:44:51.731 only even packets)
3. ECM for next odd key came at 23:44:48.227, but the reply from oscam did not come until 23:44:51.975 ~250msec late.
(oscam showed 3748msec time to retrieve key)
5. After the key arrived, tvheadend continued to queue packets (all odd_) until 23:44:53.119 then the error "cannot decode packets" and then flush2, then the odd key was set and descrambling starts again. I am not sure why the new key was not set immediately after being received at 23:44:51.975???
4. In the source code, dr_ecm_key_margin is set to the 1/5 of the initial interval (default of 10sec) and is never updated when the interval changes.
5. the interval shown in the logs is actually .8 * interval ( interval - interval/5) so 12xxx ~= 15sec and 22xxx ~=28sec
There is nothing tvheadend can do about the occasional slow key response from oscam.
Maybe dynamically updating the margin may help??
Maybe adding an entry in data/conf/descrambler for CAID 1810 with an interval of 15000 will help??
Updated by saen acro about 6 years ago
Oscam cut late key after 5000ms.
STB wait less from local card reader
Updated by Jaroslav Kysela about 6 years ago
Joe User wrote:
5. After the key arrived, tvheadend continued to queue packets (all odd_) until 23:44:53.119 then the error "cannot decode packets" and then flush2, then the odd key was set and descrambling starts again. I am not sure why the new key was not set immediately after being received at 23:44:51.975???
Yes, that's exactly the point. The code https://github.com/tvheadend/tvheadend/commit/4b3b0aab4ea669f612d3db29b79e016252c939fb should resolved this (it should insert the key change request to the start of the queue). But perhaps, I overlooked something. Anyway, the key provider is too slow and there seems to be a protection from the broadcaster (quick ECM/key change).
Updated by Pablo R. about 6 years ago
I think that tvheadend is incorrectly considering as a late key when an interval change occurs. In comment #7 version 4.3-1453 of tvheadend is used with the default buffer configuration (9000) - see attached log. If necessary I can create another log with buffer of 20000 packets.
Joe User wrote:
5. After the key arrived, tvheadend continued to queue packets (all odd_) until 23:44:53.119 then the error "cannot decode packets" and then flush2, then the odd key was set and descrambling starts again. I am not sure why the new key was not set immediately after being received at 23:44:51.975???
I think the problem is there. Why tvheadend is buffering when key is already received? When descrambling resets all starts to works fine (with same key)
saen acro wrote:
Oscam cut late key after 5000ms.
STB wait less from local card reader
2018-10-08 16:30:25.163 [ DEBUG]:descrambler: info - service='BEIN LALIGA' caid=1810(nagra) provid=000000 ecmtime=1069 hops=2 reader='T' from='192.168.2.197' protocol='cccam_ext' ^^^ ecm received 2018-10-08 16:30:25.454 [ ERROR]:descrambler: cannot decode packets for service "BEIN LALIGA" ^^^ errors with buffer or so 2018-10-08 16:30:26.180 [ TRACE]:descrambler: cannot decode packets for service "BEIN LALIGA" 2018-10-08 16:30:26.180 [ TRACE]:descrambler: 0x7f855000a3d0: data append 188, timestamp 5651103806, even[167] 2018-10-08 16:30:26.180 [ TRACE]:descrambler: 0x7f855000a3d0: end, even 2018-10-08 16:30:26.180 [ TRACE]:descrambler: 0x7f855000a3d0: key[0] flush2 2018-10-08 16:30:26.181 [ TRACE]:descrambler: 0x7f855000a3d0: even key[0] set for decoder 2018-10-08 16:30:26.181 [ TRACE]:descrambler: 0x7f855000a3d0: key[0] flush2 2018-10-08 16:30:26.181 [ TRACE]:descrambler: 0x7f855000a3d0: odd key[0] set for decoder [...] ^^^ descrambling resets No more errors, next key change at 16:30:39. 2018-10-08 16:30:39.436 [ DEBUG]:descrambler: info - service='BEIN LALIGA' caid=1810(nagra) provid=000000 ecmtime=370 hops=2 reader='T' from='192.168.2.197' protocol='cccam_ext'
I dont think it is a card latency issue, look last log, latency on oscam (dvbapi) is about 1100ms before the problem occurs.
Updated by Joe User about 6 years ago
Pablo R. wrote:
I dont think it is a card latency issue, look last log, latency on oscam (dvbapi) is about 1100ms before the problem occurs.
That time was for the new odd key, the new even key came from oscam at the same time, but was sent to oscam at 16:30:19.977, so >5sec (odd ecm was sent at 16:30:24.088 = 1100msec)
Need corresponding oscam log to see why..
Updated by saen acro about 6 years ago
is oscam on first hop have CACHE activated?
This will keep key as long as it need /set in settings/
Maby some cache need to be stored by TVH itself last five of type per channel aka even/odd
and if fall to retry with latest or previous.
Updated by Jaroslav Kysela about 6 years ago
I think that I found it: v4.3-1456-ged5fd6303 . Commit https://github.com/tvheadend/tvheadend/commit/ed5fd630318e0ee469015cc7161265f01186f653 . The key should be inserted before the queued data so they should be descrambled ASAP as the key is received.
Updated by Pablo R. about 6 years ago
Jaroslav Kysela wrote:
Feedback?
Now it works much better, errors still appears but I can't ensure if they are a buffer problem or a late ecm.
I need more time to test this.
In any case, good work!
Updated by Pablo R. about 6 years ago
Pablo R. wrote:
[...] errors still appears [...]
Much fewer errors appear than before.
Updated by Pablo R. about 6 years ago
It is definitely solves (/). Thanks for the support.
P.S.: Is a backport possible to v4.2?
Updated by da h4xX0rz1sT about 6 years ago
If you look at the diff, a backport doesn't seem to come for free. Lots of changes.
$ git diff --stat release/4.2..master src/descrambler/descrambler.c src/descrambler/descrambler.c | 1134 ++++++++++++++++++++++++++++++++++++++++++++++---------------------- 1 file changed, 774 insertions(+), 360 deletions(-)
Maybe someone who is deep in the code of tvheadend can do it - if it is a priority, or worth the work.
HTH,
/HXZ
Updated by Jaroslav Kysela about 6 years ago
- Status changed from New to Fixed
I don't plan to backport this to 4.2 (the queuing mechanism is a bit different).
Updated by da h4xX0rz1sT about 6 years ago
After 24h test, it seems fixed here, too. No more such error messages. Thanks
HTH,
/HXZ
Updated by Pablo R. about 6 years ago
Jaroslav Kysela wrote:
I don't plan to backport this to 4.2 (the queuing mechanism is a bit different).
Ok, no problem. Thanks for all!
da h4xX0rz1sT wrote:
After 24h test, it seems fixed here, too. No more such error messages. Thanks
HTH,
/HXZ
Happy to hear this too