Bug #4406: Errors occur in decryption - Tvheadend

Custom queries

Accepted bugs by category
Bugs by category
Bugs by priority
Bugs by status
Bugs by target version
Features by category
Features by target version
Issues by category
Issues by status
Issues by target version
Need feedback by date
New issues
Status for next release

Actions

Copy link

Bug #4406

closed

Errors occur in decryption

Added by Pablo R. almost 8 years ago. Updated over 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

Download all 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
Notes
Property changes

Actions

Copy link

Updated by Jaroslav Kysela almost 8 years ago

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

Actions

Copy link Download all files

Updated by Pablo R. almost 8 years ago

File log.txt log.txt added
File oscam.log oscam.log added

Here is an error at 16:07:06.901

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

Actions

Copy link

Updated by Jaroslav Kysela almost 8 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.

Actions

Copy link Download all files

Updated by Pablo R. almost 8 years ago

File log.txt log.txt added
File oscam.log oscam.log added

21:48:52.487

Actions

Copy link

Updated by Pablo R. almost 8 years ago

If you need more probes or something else tell me.

Actions

Copy link Download all files

Updated by Pablo R. almost 8 years ago

File oscamsimp.txt oscamsimp.txt added
File simpl.txt simpl.txt added

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

22:04:37.735

Actions

Copy link

Updated by Jaroslav Kysela almost 8 years ago

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

Applied in changeset commit:tvheadend|f947a92ace9283ead415a62780936d0209946490.

Actions

Copy link

Updated by Jaroslav Kysela almost 8 years ago

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

Actions

Copy link Download all files

Updated by Pablo R. almost 8 years ago

File oscam2.txt oscam2.txt added
File tvh.txt tvh.txt added

13:43:22.275
13:43:38.885

I update to v4.3-186.

2 problems there... Perhaps the problem continues?

Actions

Copy link

#10

Updated by Jaroslav Kysela almost 8 years ago

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

Actions

Copy link

#11

Updated by Pablo R. almost 8 years ago

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

Actions

Copy link

#12

Updated by Pablo R. almost 8 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.

Actions

Copy link

#13

Updated by Jaroslav Kysela almost 8 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.

Actions

Copy link

#14

Updated by Mirko Di Paolo almost 8 years ago

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

Actions

Copy link Download all files

#15

Updated by Pablo R. almost 8 years ago

File oscam.log oscam.log added
File log.txt log.txt added

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.

Actions

Copy link

#16

Updated by Jaroslav Kysela almost 8 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 ?

Actions

Copy link

#17

Updated by Pablo R. almost 8 years ago

Woow!! It is fixed now.

Thanks!!!

Actions

Copy link Download all files

#18

Updated by Pablo R. almost 8 years ago

File oscamt.txt oscamt.txt added
File logt.txt logt.txt added

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

23:04:57.734

Actions

Copy link

#19

Updated by Mirko Di Paolo almost 8 years ago

File log log added

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

Actions

Copy link

#20

Updated by Mirko Di Paolo almost 8 years ago

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

I have local cards.

Actions

Copy link

#21

Updated by Jaroslav Kysela almost 8 years ago

Try v4.3-195-g50fa8fd .

Actions

Copy link Download all files

#22

Updated by Pablo R. almost 8 years ago

File _usr_bin_tvheadend.0.crash _usr_bin_tvheadend.0.crash added
File tvheadend_4.3-195-g50fa8fd-xenial_amd64.deb tvheadend_4.3-195-g50fa8fd-xenial_amd64.deb added

I just get a crash. Idk if this could help anything.

Actions

Copy link

#23

Updated by Jaroslav Kysela almost 8 years ago

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

Actions

Copy link

#24

Updated by Mark Clarkstone almost 8 years ago

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

Actions

Copy link Download all files

#25

Updated by Pablo R. almost 8 years ago

File error1.txt error1.txt added
File error2.txt error2.txt added

Descrambling errors there

Actions

Copy link

#26

Updated by Pablo R. almost 8 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)

Actions

Copy link

#27

Updated by Jaroslav Kysela almost 8 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.

Actions

Copy link

#28

Updated by Pablo R. almost 8 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. :(

Actions

Copy link

#29