Tvheadend

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 :P

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.

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

Could this issue be assigned as pending? (top one) :)

Thanks.

Retest with v4.3-1453-g4b3b0aab4 .

Those messages are not handled with the proposed fix (yet), but the picture should be better.

Also you should increase the descrambler buffer size in the global config (value 20000 or so).

Now that I increased buffer to 20000 from 9000 there are more errors

Is it better to disable buffer? (set it to 0).

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?

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.

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??

Oscam cut late key after 5000ms.
STB wait less from local card reader

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).

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'

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..

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.

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.

Feedback?

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!

Pablo R. wrote:

[...] errors still appears [...]

Much fewer errors appear than before.

It is definitely solves (/). Thanks for the support.

P.S.: Is a backport possible to v4.2?

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

After 24h test, it seems fixed here, too. No more such error messages. Thanks :)

HTH,
/HXZ

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 :)