Project

General

Profile

Bug #5659

Bug #5459: Something is slow in 4.3

Descrambler issues in 4.3

Added by Robin Mitra about 1 month ago. Updated 14 days ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
Descrambling
Target version:
-
Start date:
2019-06-16
Due date:
% Done:

0%

Estimated time:
Found in version:
4.3 since Dec 25 2017 !!!
Affected Versions:

Description

As described (in a convoluted way) in issue #5459, I've been unable to use 4.3 for auite some time now due to descrambling fails every few seconds.
my setup is a ivy bridge i7 with 2 dual sat tuners from digitaldevices.
Everything works fine in the released 4.2.8-23~g74cdf3f16.

I've taken the time to trace back to where the problems start:
The last working version is
1156bf17439c67d52510cfa0738042de47478f92
Date: Mon Dec 25 2017 18:07:59 GMT+0100 (Central European Standard Time)

the commit after that started fiddling with cwc, newcamd and broke descrambling:
Commit: c69368baef8022563b2d6646082268e59983048c
Parents: 1156bf17439c67d52510cfa0738042de47478f92
Author: Jaroslav Kysela <>
Date: Mon Dec 25 2017 18:17:27 GMT+0100 (Central European Standard Time)
Committer: Jaroslav Kysela
cwc, newcamd: add detection for DVN ECM message, issue #4813

After further commits to fix this commit it got somewaht better, but never to the stability of before.

The way I test this is simple:
watch a scrambled channel, and start the OTA grabber on the remaining 3 tuners... I get scrambling errors (due to packet loss or whatever) evry few seconds as long as the OTA is running.
Even after OTA, using any of teh other tuners to tune to a service will more likely than not create a descrambling issue.

The other problem I mentioned in #5459 (slow OTA grab) seems unrelated to this issue, but still persists.


Files

Associated revisions

Revision 6be300c4 (diff)
Added by Jaroslav Kysela 15 days ago

cclient: fix the ECM PID flag for newcamd and cccam, fixes #5659

History

#1

Updated by Jaroslav Kysela about 1 month ago

Show traces: '--trace descrambler,cwc,cccam' - https://tvheadend.org/projects/tvheadend/wiki/Traces

#2

Updated by Jaroslav Kysela about 1 month ago

  • Status changed from New to Rejected
  • Parent task set to #5459
#3

Updated by Robin Mitra about 1 month ago

traces already were provided in #5459

#4

Updated by Jaroslav Kysela about 1 month ago

No, the logs do not have any TRACE lines. See my last comment.

#5

Updated by Robin Mitra about 1 month ago

hmm I remeber trying to get all possible traces and the log was quite big.
Anyway the system is in use now so I can play with it only coming weekend.
When I do so, please tell me how exactly you want me enable the traces above (if not just in zhe web ui)

Which commit should I test ? IIRC the (channels etc)config I currently have is 4.2 and at some point it wasn't usable anymore in 4.3.
I'd like to avoid having to setup all the channels again.
Also using the latest commit will suffer from a different issue (really slow eit grab).

#6

Updated by Pablo R. about 1 month ago

Robin Mitra wrote:

hmm I remeber trying to get all possible traces and the log was quite big.
Anyway the system is in use now so I can play with it only coming weekend.
When I do so, please tell me how exactly you want me enable the traces above (if not just in zhe web ui)

Attach log with traces (commonly huge size) -> descrambler,cwc,cccam

On webui:
Configuration -> Debugging ->
  • Set Filename (including path)
  • Tick Debug trace (low-level)
  • Trace subsystems: descrambler,cwc,cccam
#7

Updated by Robin Mitra 29 days ago

I've add 2 logs .
One working with commit 1156bf17439c67d52510cfa0738042de47478f92
the second one from a commit a few days later when descrambling on single channels seems to work again, but has lots of errors when eit is runuing on other tuners

#8

Updated by Jaroslav Kysela 27 days ago

It looks like that there is no bug in the descrambler at the first look. The ECMs are "fast" ones (the key must be used within 500ms - half a second - when the ECM is received). It seems that the data flow inside the recent tvh is not so fast for a reason (something blocks the ECM processing). The key is required early than the ECM is sent to the key server. Show the log with all traces for the recent tvh with this extra code:

diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index 71cc9ebd6..b83f1d6aa 100644
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -1341,6 +1341,10 @@ descrambler_table_callback
   }
   tvh_mutex_unlock(&mt->mt_mux->mm_descrambler_lock);

+  if (!emm)
+    tvhtrace(LS_DESCRAMBLER, "ECM message %02x:{%02x:%02x}:%02x (len %d, pid %d)",
+             ptr[0], ptr[1], ptr[2], ptr[3], len, mt->mt_pid);
+
   LIST_FOREACH(des, &sections, active_link) {
     if (des->changed == 2) {
       des->callback(des->opaque, mt->mt_pid, ptr, len, emm);
#9

Updated by Robin Mitra 26 days ago

I agree that something is slower. I will try it out coming weekend.

Note that his happened way back in Dec/2017 - Jan/2018 long before you changed to using libdvbsa instead of ffdecsa. So it seems to have nothing to do with that.
Also, the released 4.2 doesn't show this behaviour.

#10

Updated by Robin Mitra 22 days ago

here goes, using current master, applied your patch:
a log for 5 mins with 1 channel being watched and 3 tuners doing an eit grab.
Eit grab is fast again now (
5mins, as opposed to > 30mins a few commits ago)

I don't see the descrambler or any thing else being slow per se.
It's more like the established descrambling pipeline is sharing some resource being locked for an unusually long time when the eit grabber (or anyone else) tries to build a new streaming pipeline.

#11

Updated by Jaroslav Kysela 20 days ago

The patch was not applied. The problem is that ECM is not detected/sent before the key change in some cases.

EDIT: You may verify the patch - there should be 'ECM message' lines in the TRACE log without 'for service' words.

#12

Updated by Robin Mitra 15 days ago

next try.

Again, I don't see why the descrambler is being disturbed at all when tuning on a different tuner. The ECM not being seen is IMHO only the result of something else being blocked for longer than it needs to be.

But that is of course only an observation and analogy (a 'gut feeling') of having programmed other stuff for a living for > 40 yrs.

#13

Updated by Robin Mitra 15 days ago

BTW,
I went back to the builds of dec 25 2017 and had a closer look.
That is not the commit that introducedd this behaviour. I was mistatken due to another bug in that commit.
Right now I'm looking at the time frame from Jan 25. 2018 (working) and Jan 31. 2018 (bad).

Shouldn't be to hard to pinpoint now...

#14

Updated by Jaroslav Kysela 15 days ago

  • Status changed from Rejected to Fixed

Mea culpa. I forgot to flag the ECM PIDs in the common cclient code (newcamd, cccam). So they were evaluated in the slow EMM path. Could you try latest? v4.3-1802-g6be300c43

#15

Updated by Robin Mitra 14 days ago

Yup,
that fixed it.
thanks.

#16

Updated by Pablo R. 14 days ago

Jul  7 11:19:52 dell tvheadend[6642]: CRASH: Signal: 11 in PRG: /usr/bin/tvheadend (4.3-1802~g6be300c43) [921a17bbb26f4ae358b76c511e7122722ccce354] CWD: /
Jul  7 11:19:52 dell tvheadend[6642]: CRASH: Fault address 0xb0 (Address not mapped)
Jul  7 11:19:52 dell tvheadend[6642]: CRASH: Loaded libraries: linux-vdso.so.1 /usr/lib/x86_64-linux-gnu/libdvbcsa.so.1 /usr/lib/x86_64-linux-gnu/libssl.so.1.1 /usr/lib/x86_6$
Jul  7 11:19:52 dell tvheadend[6642]: CRASH: Register dump [23]: 00005599f45b08b000000000000000000000000000000005000000000000000000000000000000a000007f0c575f95100000000000000$
Jul  7 11:19:52 dell tvheadend[6642]: CRASH: STACKTRACE
Jul  7 11:19:52 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/trap.c:176 0x5599f261f53d 0x5599f240a000
Jul  7 11:19:53 dell tvheadend[6642]: CRASH: ??:0 0x7f0caa9bd890 0x7f0caa9ab000
Jul  7 11:19:53 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/descrambler/cclient.c:883 0x5599f270ba81 0x5599f240a000
Jul  7 11:19:53 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/descrambler/descrambler.c:1346 0x5599f2699341 0x5599f240a000
Jul  7 11:19:53 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/input/mpegts/mpegts_table.c:101 0x5599f26b1a03 0x5599f240a000
Jul  7 11:19:53 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/input/mpegts/dvb_psi_lib.c:135 (discriminator 4) 0x5599f26a7dd2 0x5599f240a000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/input/mpegts/dvb_psi_lib.c:185 0x5599f26a8237 0x5599f240a000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/input/mpegts/mpegts_input.c:1338 (discriminator 3) 0x5599f26a09fb 0x5599f240a000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/input/mpegts/mpegts_input.c:1544 0x5599f26a3fac 0x5599f240a000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: /project/repo/checkout/src/tvh_thread.c:91 0x5599f25df988 0x5599f240a000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: ??:0 0x7f0caa9b26db 0x7f0caa9ab000
Jul  7 11:19:54 dell tvheadend[6642]: CRASH: clone+0x3f  (/lib/x86_64-linux-gnu/libc.so.6)
Jul  7 11:19:54 dell kernel: [415886.850582] show_signal_msg: 9 callbacks suppressed
Jul  7 11:19:54 dell kernel: [415886.850584] tvh:mi-main[6713]: segfault at b0 ip 00005599f270ba81 sp 00007f0c575f93f0 error 4 in tvheadend[5599f240a000+14be000]
#17

Updated by Pablo R. 14 days ago

Thread 84 "tvh:mi-main" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f89511e8700 (LWP 15786)]
cc_table_input (opaque=0x7f898409e560, pid=2000, data=0x7f898402d720 "\200pdpbdX(\370\256.\371'\021\240\[email protected]\273Z3H\356\064\345\370\354p\275\335s\210\[email protected]\020\340\342\033P\221\005\376\027x\302\226aH\335xzD\232|\344V,\200\373\352\362\272\227\216U\207D\215\021\257\\\003\064FU\303ic<\317V\245i\022\273o\362\223Q\231h+ID\217\250\037\232ƌ\034\261v\213", '\377' <repeats 80 times>, len=103, emm=<optimized out>) at src/descrambler/cclient.c:884
warning: Source file is more recent than executable.
884        if(ep->ep_capid == pid) break;

#0  cc_table_input (opaque=0x7f898409e560, pid=2000, data=0x7f898402d720 "\200pdpbdX(\370\256.\371'\021\240\[email protected]\273Z3H\356\064\345\370\354p\275\335s\210\[email protected]\020\340\342\033P\221\005\376\027x\302\226aH\335xzD\232|\344V,\200\373\352\362\272\227\216U\207D\215\021\257\\\003\064FU\303ic<\317V\245i\022\273o\362\223Q\231h+ID\217\250\037\232ƌ\034\261v\213", '\377' <repeats 80 times>, len=103, emm=<optimized out>) at src/descrambler/cclient.c:884
#1  0x0000562407636341 in descrambler_table_callback (mt=<optimized out>, ptr=<optimized out>, len=103, tableid=<optimized out>) at src/descrambler/descrambler.c:1346
#2  0x000056240764ea03 in mpegts_table_dispatch (sec=<optimized out>, r=<optimized out>, aux=0x7f898402d6b0) at src/input/mpegts/mpegts_table.c:101
#3  0x0000562407644dd2 in mpegts_psi_section_reassemble0 ([email protected]=0x7f898402d6b0, [email protected]=0x7f898406b440 "11973V in Astra V+", [email protected]=0x7f893c06a5b6 "\200pdpbdX(\370\256.\371'\021\240\[email protected]\273Z3H\356\064\345\370\354p\275\335s\210\[email protected]\020\340\342\033P\221\005\376\027x\302\226aH\335xzD\232|\344V,\200\373\352\362\272\227\216U\207D\215\021\257\\\003\064FU\303ic<\317V\245i\022\273o\362\223Q\231h+ID\217\250\037\232ƌ\034\261v\213", '\377' <repeats 80 times>, "G\017\253Ւ\n\357s\n\357P\210\r\f\021", <incomplete sequence \326>..., [email protected]=183, [email protected]=64, [email protected]=0, cb=0x56240764e970 <mpegts_table_dispatch>, opaque=0x7f898402d6b0) at src/input/mpegts/dvb_psi_lib.c:135
#4  0x0000562407645237 in mpegts_psi_section_reassemble ([email protected]=0x7f898402d6b0, [email protected]=0x7f898406b440 "11973V in Astra V+", [email protected]=0x7f893c06a5b1 "GG\320\026", crc=0, cb=0x56240764e970 <mpegts_table_dispatch>, [email protected]=0x7f898402d6b0) at src/input/mpegts/dvb_psi_lib.c:185
#5  0x000056240763d9fb in mpegts_input_table_dispatch ([email protected]=0x56240a2b7900, logprefix=0x7f898406b440 "11973V in Astra V+", [email protected]=0x7f893c06a5b1 "GG\320\026", [email protected]=188, [email protected]=1) at src/input/mpegts/mpegts_input.c:1338
#6  0x0000562407640fac in mpegts_input_process (mpkt=<optimized out>, mi=<optimized out>) at src/input/mpegts/mpegts_input.c:1544
#7  mpegts_input_thread (p=<optimized out>) at src/input/mpegts/mpegts_input.c:1743
#8  0x000056240757c988 in thread_wrapper (p=0x7f89840069d0) at src/tvh_thread.c:91
#9  0x00007f89b2e1d6db in start_thread (arg=0x7f89511e8700) at pthread_create.c:463
#10 0x00007f89b1fed88f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
Detaching from program: /usr/bin/tvheadend, process 15700

Also available in: Atom PDF