Project

General

Profile

Bug #4406

Errors occur in decryption

Added by Pablo R. over 7 years ago. Updated almost 7 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
Start date:
2017-05-31
Due date:
% Done:

100%

Estimated time:
Found in version:
4.3-182
Affected Versions:

Description

Over several hours decrypting channels with oscam (dvbapi), while oscam reflects that all packets sent are OK (0 NOK), tvheadend fails to decrypt sometimes. When these were correct, in fact I have activated the double-check in oscam. Tvheadend log shows ECM late or another errors and channel freezes. This happens about 2 or 3 times per hour.

The same happens to me with the local card.

This has taken me a while now but it seems that now the problem has increased.

Files

log.txt (94.4 KB) log.txt Pablo R., 2017-06-01 16:20
oscam.log (2.77 MB) oscam.log Pablo R., 2017-06-01 16:20
log.txt (5.08 MB) log.txt Pablo R., 2017-06-01 22:01
oscam.log (6.73 MB) oscam.log Pablo R., 2017-06-01 22:01
oscamsimp.txt (429 KB) oscamsimp.txt Pablo R., 2017-06-01 22:33
simpl.txt (320 KB) simpl.txt Pablo R., 2017-06-01 22:33
oscam2.txt (647 KB) oscam2.txt Pablo R., 2017-06-04 13:59
tvh.txt (911 KB) tvh.txt Pablo R., 2017-06-04 13:59
oscam.log (4.91 MB) oscam.log Pablo R., 2017-06-05 16:19
log.txt (11.4 MB) log.txt Pablo R., 2017-06-05 16:22
oscamt.txt (1.46 MB) oscamt.txt Pablo R., 2017-06-05 23:12
logt.txt (2.16 MB) logt.txt Pablo R., 2017-06-05 23:12
log (370 KB) log Mirko Di Paolo, 2017-06-05 23:54
_usr_bin_tvheadend.0.crash (19.6 MB) _usr_bin_tvheadend.0.crash Pablo R., 2017-06-06 17:33
tvheadend_4.3-195-g50fa8fd-xenial_amd64.deb (9.1 MB) tvheadend_4.3-195-g50fa8fd-xenial_amd64.deb Pablo R., 2017-06-06 17:34
error1.txt (2.34 MB) error1.txt Pablo R., 2017-06-06 20:47
error2.txt (2.38 MB) error2.txt Pablo R., 2017-06-06 20:47

History

#1

Updated by Jaroslav Kysela over 7 years ago

Provide '--trace descrambler,capmt' from tvheadend and anonymized log from oscam - level 128. https://tvheadend.org/projects/tvheadend/wiki/Traces

#2

Updated by Pablo R. over 7 years ago

Here is an error at 16:07:06.901

If more errors are necessary I can add them, in fact I continuous with logging. :)

#3

Updated by Jaroslav Kysela over 7 years ago

Provide TRACES for tvh (follow the link I sent you in comment 1!). I see the gap in the processing between 16:06:54...16:07:07, but I'm not able to analyze the problem from the DEBUG only log.

#4

Updated by Pablo R. over 7 years ago

21:48:52.487

#5

Updated by Pablo R. over 7 years ago

If you need more probes or something else tell me.

#6

Updated by Pablo R. over 7 years ago

Here, maybe a more clearly example of errors (invalid key)

22:04:37.735

#7

Updated by Jaroslav Kysela over 7 years ago

  • Status changed from New to Fixed
  • % Done changed from 0 to 100

Applied in changeset commit:tvheadend|f947a92ace9283ead415a62780936d0209946490.

#8

Updated by Jaroslav Kysela over 7 years ago

This should be fixed in v4.3-186-gf947a92 .

#9

Updated by Pablo R. over 7 years ago

13:43:22.275
13:43:38.885

I update to v4.3-186.

2 problems there... Perhaps the problem continues?

#10

Updated by Jaroslav Kysela over 7 years ago

It's different one. Most probably errors in the reception path.

#11

Updated by Pablo R. over 7 years ago

What do you mean? That problems are caused by a bad satellite signal or faults with cccam lines?

#12

Updated by Pablo R. over 7 years ago

I just tested 4.2.2-35~g60e4409

And problem doesn't exists :o
Problem of invalid keys and ECM late's is only on master branch... I guess.

#13

Updated by Jaroslav Kysela over 7 years ago

The log in comment 9 contains TS stream which switches odd/even keys very fastly at a time (so probably a wrong TS packet was injected somewhere - I suppose it was received).

I added more code which should handle this more gracefully in v4.3-190-g7c9732b, but I always need logs to analyze the issue.

#14

Updated by Mirko Di Paolo over 7 years ago

Same issue here. Reverting to commit e0a31ace29926f89b552ffaf5fd02b98780beff1 problem disappear.
Tonight I will try the new fix.

#15

Updated by Pablo R. over 7 years ago

Problem still occurs... But it is less frequent.

16:08:44.957
16:08:34.959
16:08:24.980
16:06:39.148
16:06:37.895
16:06:28.684

I'm not sure how the decoding system works but I think there's something confusing about even and odd packets.

As Mirko Di Paolo says, before the changes in campt and descramble (as in 4.2.2) this problem did not happen.

#16

Updated by Jaroslav Kysela over 7 years ago

This issue is for:

2017-06-05 16:08:23.041 [  TRACE]:descrambler: stream key[0] changed to even for service "LA SEXTA HD" 
2017-06-05 16:08:23.041 [  TRACE]:descrambler: stream key[0] changed to odd for service "LA SEXTA HD"

I think that I found another little bug (missing time conversion). Could you try: v4.3-191-g45c085a ?

#17

Updated by Pablo R. over 7 years ago

Woow!! It is fixed now.

Thanks!!!

#18

Updated by Pablo R. over 7 years ago

It has given me some trouble (cannot decode packets) but now they are much less common than before.

23:04:57.734

#19

Updated by Mirko Di Paolo over 7 years ago

Works better but I got some glitches and audio stuttering, reverting to an old version works.

#20

Updated by Mirko Di Paolo over 7 years ago

After some test seems issue start with commit 99e9a2af9d0eca9213af2b0051a96e39e77f97bb descrambler: add multi-pid descrambling

I have local cards.

#21

Updated by Jaroslav Kysela over 7 years ago

Try v4.3-195-g50fa8fd .

#23

Updated by Jaroslav Kysela over 7 years ago

Give me the CRASH lines with symbols: https://tvheadend.org/projects/tvheadend/wiki/Debugging

#24

Updated by Mark Clarkstone over 7 years ago

-- Removed log as it isn't actually useful without debugging symbols - ref #4411 --

#25

Updated by Pablo R. over 7 years ago

Descrambling errors there

#26

Updated by Pablo R. over 7 years ago

Crash with symbols:

2017-06-06 20:55:06.597 [  ALERT]:CRASH: Signal: 11 in PRG: /usr/bin/tvheadend (4.3-195~g50fa8fd) [b1e07afe9d667805d9abc6c86e21d7bf6fb913b1] CWD: /  
2017-06-06 20:55:06.598 [  ALERT]:CRASH: Fault address 0x3 (Address not mapped)
2017-06-06 20:55:06.598 [  ALERT]:CRASH: Loaded libraries: /usr/lib/libdvben50221.so /usr/lib/libdvbapi.so /usr/lib/libucsi.so /lib/x86_64-linux-gnu/libssl.so.1.0.0 /lib/x86_64-linux-gnu/libcrypto.so.1.0.0 /lib/x86_64-linux-gnu/libz.so.1 /usr/lib/x86_64-linux-gnu/libpcre2-8.so.0 /usr/lib/x86_64-linux-gnu/liburiparser.so.1 /usr/lib/x86_64-linux-gnu/libavahi-common.so.3 /usr/lib/x86_64-linux-gnu/libavahi-client.so.3 /lib/x86_64-linux-gnu/libdbus-1.so.3 /lib/x86_64-linux-gnu/libdl.so.2 /lib/x86_64-linux-gnu/libpthread.so.0 /lib/x86_64-linux-gnu/libm.so.6 /lib/x86_64-linux-gnu/librt.so.1 /usr/lib/x86_64-linux-gnu/libstdc++.so.6 /lib/x86_64-linux-gnu/libc.so.6 /lib/x86_64-linux-gnu/libsystemd.so.0 /lib64/ld-linux-x86-64.so.2 /lib/x86_64-linux-gnu/libgcc_s.so.1 /lib/x86_64-linux-gnu/libselinux.so.1 /lib/x86_64-linux-gnu/liblzma.so.5 /lib/x86_64-linux-gnu/libgcrypt.so.20 /lib/x86_64-linux-gnu/libpcre.so.3 /lib/x86_64-linux-gnu/libgpg-error.so.0 /lib/x86_64-linux-gnu/libnss_compat.so.2 /lib/x86_64-linux-gnu/libnsl.so.1 /lib/x86_64-linux-gnu/libnss_n
2017-06-06 20:55:06.598 [  ALERT]:CRASH: Register dump [23]: 00000000000000d600000000000000010000000000000000000000000000004000007efc68056aa000000000000000d8000000000000000000007efc68059171000000000000000c000000000000000300000000000000c000007efc68056ae0000000000000000000007efc88073560000000000000000000007efc46bf46100000563e0a563d33000000000001024699380000000000330000000000000004000000000000000efffffffe7ffbba110000000000000003
2017-06-06 20:55:06.598 [  ALERT]:CRASH: STACKTRACE
2017-06-06 20:55:06.866 [  ALERT]:CRASH: /project/repo/checkout/src/trap.c:148 0x563e0a4f9b9d 0x563e0a2fe000
2017-06-06 20:55:07.214 [  ALERT]:CRASH: ??:0 0x7efcace9e390 0x7efcace8d000
2017-06-06 20:55:07.483 [  ALERT]:CRASH: /project/repo/checkout/src/descrambler/descrambler.c:175 0x563e0a563d33 0x563e0a2fe000
2017-06-06 20:55:07.759 [  ALERT]:CRASH: /project/repo/checkout/src/input/mpegts/tsdemux.c:338 0x563e0a56c8fd 0x563e0a2fe000
2017-06-06 20:55:08.065 [  ALERT]:CRASH: /project/repo/checkout/src/input/mpegts/mpegts_input.c:1332 0x563e0a569dbe 0x563e0a2fe000
2017-06-06 20:55:08.318 [  ALERT]:CRASH: /project/repo/checkout/src/wrappers.c:161 0x563e0a4bf365 0x563e0a2fe000
2017-06-06 20:55:08.585 [  ALERT]:CRASH: ??:0 0x7efcace946ba 0x7efcace8d000
2017-06-06 20:55:08.585 [  ALERT]:CRASH: clone+0x6d  (/lib/x86_64-linux-gnu/libc.so.6)
#27

Updated by Jaroslav Kysela over 7 years ago

Crash should be fixed in v4.3-198-g055e2f6.

The descrambling errors - it seems that something weird is with ECM messages for both channels (it appears like a temporary broadcasting error):

2017-06-06 18:49:13.414 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:49:13.975 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:FC2CE911B092A1E3 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:49:13.976 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:FC2CE911B092A1E3 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:49:28.421 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:49:28.967 [  TRACE]:descrambler: Obtained CSA keys 0F371C629C930938:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:49:28.968 [  TRACE]:descrambler: Obtained CSA keys 0F371C629C930938:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:49:43.422 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:49:43.989 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:EE84EE60ACC636A8 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:49:43.989 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:EE84EE60ACC636A8 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:18.603 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:50:19.034 [  TRACE]:descrambler: Obtained CSA keys 791BCD61F3EEA283:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:19.034 [  TRACE]:descrambler: Obtained CSA keys 791BCD61F3EEA283:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:21.992 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:50:22.612 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:50:22.947 [  DEBUG]:descrambler: Obtained CSA keys from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:22.947 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:C4386C68F883D44F pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:22.947 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:C4386C68F883D44F pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:37.670 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:50:38.128 [  TRACE]:descrambler: Obtained CSA keys 5AFC1C72D88D44A9:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:38.129 [  TRACE]:descrambler: Obtained CSA keys 5AFC1C72D88D44A9:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:52.660 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:50:53.116 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:8D2F8945772E51F6 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:50:53.116 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:8D2F8945772E51F6 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:51:07.658 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2244) for service "NAT GEO HD" 
2017-06-06 18:51:08.102 [  TRACE]:descrambler: Obtained CSA keys F2D1FEC17CAC83AB:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 
2017-06-06 18:51:08.102 [  TRACE]:descrambler: Obtained CSA keys F2D1FEC17CAC83AB:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "NAT GEO HD" 

2017-06-06 18:49:13.351 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:49:13.701 [  TRACE]:descrambler: Obtained CSA keys B47DEF2087E1127A:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:49:13.702 [  TRACE]:descrambler: Obtained CSA keys B47DEF2087E1127A:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:49:28.318 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:49:28.688 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:0E9F07B48607CA57 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:49:28.689 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:0E9F07B48607CA57 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:49:43.340 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:49:43.700 [  TRACE]:descrambler: Obtained CSA keys F69EE377FE4F0552:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:49:43.700 [  TRACE]:descrambler: Obtained CSA keys F69EE377FE4F0552:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:18.719 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:50:19.327 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:170D92B6DE85CA2D pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:19.327 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:170D92B6DE85CA2D pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:22.422 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:50:22.814 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:50:23.286 [  DEBUG]:descrambler: Obtained CSA keys from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:23.286 [  TRACE]:descrambler: Obtained CSA keys DD7E51ACD9EDEAB0:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:23.287 [  TRACE]:descrambler: Obtained CSA keys DD7E51ACD9EDEAB0:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:37.812 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:50:38.229 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:6CC6C5F78592C5DC pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:38.229 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:6CC6C5F78592C5DC pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:52.824 [  TRACE]:descrambler: ECM message 80 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:50:53.268 [  TRACE]:descrambler: Obtained CSA keys 6FECE23DBF481F26:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:50:53.268 [  TRACE]:descrambler: Obtained CSA keys 6FECE23DBF481F26:0000000000000000 pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:51:07.842 [  TRACE]:descrambler: ECM message 81 (section 132, len 142, pid 2147) for service "FOX HD" 
2017-06-06 18:51:08.284 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:B5DB982867CB98CA pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD" 
2017-06-06 18:51:08.285 [  TRACE]:descrambler: Obtained CSA keys 0000000000000000:B5DB982867CB98CA pid 0000 from capmt-127.0.0.1-9000 for service "FOX HD"

Look to time 18:49:43...18:50:18 there should be ECM around 18:50:00, too.

#28

Updated by Pablo R. over 7 years ago

Yesterday, I installed version 4.3-210, luckily the decryption problem has been completely fixed in this version (no more ecm late). No more failures.

Unfortunately after 4 hours of use with 4-6 channels simultaneously (dvbapi + descrambling + satip) I get the message "mpegts: too much queued table input data (over 2MB), discarding new" with one CPU core at 100% . Since that message tvheadend becomes irresponsible, does not open new channels.

I have tried using Valgrind but it is too slow and I can not recreate the problem, since with only one open channel I have pixelations.

With gdb I just do not understand how it works, I see many LWP messages during the failure that stop starts, the core file occupies +2GB so I do not understand how it works.

Cclang and sanitizers, after compiling a 60mb binary following your guide does not show me any error === ERROR ... when this memory leak occurs.

The only thing I know is that the problem did not occur in the 4.3-208, I had this version running more than a day without problems. :(

#29

Updated by Pablo R. over 7 years ago

P.S.: My bad, same on 4.3-208

#30

Updated by Jaroslav Kysela over 7 years ago

Try v4.3-211-g1c1f52c . I found another little mistake which can invoke your described behaviour.

#31

Updated by Pablo R. over 7 years ago

Descrambling readers for oscam are missing now (4.3-218).

With 4.3-216 I get missing characters as reader.

#32

Updated by Jaroslav Kysela over 7 years ago

v4.3-220-g89077d6

#33

Updated by Pablo R. almost 7 years ago

Close that

#34

Updated by Pablo R. almost 7 years ago

It's already closed. Sorry

Also available in: Atom PDF