Project

General

Profile

Bug #5314

Memory leak in sat>ip server with scrambled channels

Added by john beton about 6 years ago. Updated almost 6 years ago.

Status:
Fixed
Priority:
Normal
Category:
SAT>IP
Target version:
-
Start date:
2018-11-04
Due date:
% Done:

100%

Estimated time:
Found in version:
4.3-1519~g1222de1
Affected Versions:

Description

Hi,

I'm using 1 TT-4650CI DVBC tuner with a cccam connection to my local oscam server for descrambling. When using the sat>ip server for streaming, memory starts running full at about 1% every 45 seconds. When the memory usage is about 50%, it leads to situation where the connection to the tuner is lost. In my case after 50 minutes.

2018-11-03 14:54:45.166 [WARNING] TS: TN/314MHz/EUROSPORT HD: H264 #4301 Continuity counter error (total 1)
2018-11-03 14:54:45.166 [WARNING] TS: TN/314MHz/EUROSPORT HD: TELETEXT #4303 Continuity counter error (total 1)
2018-11-03 14:54:45.184 [WARNING] TS: TN/314MHz/EUROSPORT HD: MPEG2AUDIO @ #4302 Continuity counter error (total 1)
2018-11-03 14:54:46.080 [WARNING] subscription: 0002: service instance is bad, reason: No access
2018-11-03 14:54:48.080 [ NOTICE] subscription : 0002: No input source available for subscription "SAT>IP Slave/TN/314MHz/EUROSPORT HD" to service "TN/314MHz/EUROSPORT HD" in mux "314MHz in TN"

I tried with DVBViewer and VLC for streaming via RTSP, both have same effect.

When using http for streaming, the issue doesn't appear and tvheadend memory usage stays under 1%
The strange thing is that:

- When I start tvheadend memory usage is like 1%
- I let it run for a few minutes and then start a sat>ip connection with DVBViewer or VLC to a scrambled channel
- I see the memory going up slowly. About 1% every 45 seconds.
- If the RTSP connection is stopped, memory usage goes back to normal.

The issue does not appear when streaming FTA channels or when streaming scrambled channels over http. The issue is present both with a CI module and cccam connection to oscam. I tried multiple distro's ubuntu 14.04 16.04 18.04 the issue is present on all kernels.

The valgrind log eats 100% cpu and some kind of overflow occurs which kills the satip connection.

2018-11-03 20:11:09.755 [WARNING] TS: TN/314MHz/EUROSPORT HD: H264 #4301 Continuity counter error (total 1)
2018-11-03 20:11:14.896 [WARNING] linuxdvb: Silicon Labs Si2168 #0 : DVB-C #0 - read() EOVERFLOW
2018-11-03 20:11:21.510 [WARNING] TS: TN/314MHz/EUROSPORT HD: H264 #4301 Continuity counter error (total 3)
2018-11-03 20:11:21.532 [WARNING] TS: TN/314MHz/EUROSPORT HD: TELETEXT #4303 Continuity counter error (total 1)
2018-11-03 20:11:21.532 [WARNING] TS: TN/314MHz/EUROSPORT HD: MPEG2AUDIO #4302 Continuity counter error (total 1)
2018-11-03 20:11:27.349 [WARNING] linuxdvb: Silicon Labs Si2168 #0 : DVB-C #0 - read() EOVERFLOW
2018-11-03 20:11:32.770 [WARNING] linuxdvb: Silicon Labs Si2168 #0 : DVB-C #0 - read() EOVERFLOW
2018-11-03 20 :11:35.499 [WARNING] linuxdvb: Silicon Labs Si2168 #0 : DVB-C #0 - read() EOVERFLOW
2018-11-03 20:11:37.700 [ INFO] subscription: 0002: "SAT>IP Slave/TN/314MHz/EUROSPORT HD" unsubscribing, client="SAT>IP Slave/TN/314MHz/EUROSPORT HD"
2018-11-03 20:11:39.268 [WARNING] linuxdvb: Silicon Labs Si2168 #0 : DVB-C #0 - read() EOVERFLOW
2018-11-03 20:11:40.023 [ INFO] subscription: 0001: "SAT>IP" unsubscribing, hostname="192.168.1.2"

I really don't have reception problems because I can easily stream an FTA channel without any issues.. also during my valgrind command.
FTA channels only use about 80% of CPU when running the valgrind command.

So, somewhere still a problem with satip-server and descrambling?

The valgrind log seems to have some usefull information already. If you need more logs, please let me know.


Files

tvh1.log (52.8 KB) tvh1.log john beton, 2018-11-04 14:14
valgrind.log (36.5 KB) valgrind.log john beton, 2018-11-04 14:14
tvheadend (57.7 MB) tvheadend john beton, 2018-11-04 14:15
tvh5.log (162 KB) tvh5.log john beton, 2018-11-07 20:26
tvh8scrambled.log (20 MB) tvh8scrambled.log john beton, 2018-11-08 22:53
FTA.png (21.5 KB) FTA.png john beton, 2018-11-08 22:54
SCRAMBLED.png (21.2 KB) SCRAMBLED.png john beton, 2018-11-08 22:54

History

#1

Updated by Jaroslav Kysela about 6 years ago

The valgrind shows nothing useful for this. There are only avahi/dbus leaks which are not relevant. The dvbcsa uninitialized memory is also fine (and it's ignored in support/valgrind.supp (use "valgrind --suppressions=support/valgrind.supp")). You may also use cclang to detect the unfreed memory (it's faster): https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption

#2

Updated by john beton about 6 years ago

Hi,

I compiled tvheadend again with the following script:

#!/bin/sh
make distclean
ARGS="--enable-trace --enable-debugging --enable-ccdebug"
SANITIZER=leak # or address
export CFLAGS="-fsanitize=$SANITIZER"
export LDFLAGS="-fsanitize=$SANITIZER"
./configure $ARGS --disable-pie --enable-ccdebug python=python3 cc=clang ld=clang nowerror
make -j4

Because Ubuntu 16.04 uses a version suffix for llvm-symbolizer (/usr/bin/llvm-symbolizer-3.8) I created a symlink but this doesn't seem to work either. The error logs don't show resolved function names.

ASAN_OPTIONS=symbolize=1 ASAN_SYMBOLIZER_PATH=/usr/bin/llvm-symbolizer-3.8 /home/probook/tvheadend/build.linux/tvheadend -l tvhclang3.log --trace satip,linuxdvb,subscription --noacl -D

or

ASAN_OPTIONS=symbolize=1 ASAN_SYMBOLIZER_PATH=/usr/bin/llvm-symbolizer /home/probook/tvheadend/build.linux/tvheadend -l tvhclang3.log --trace satip,linuxdvb,subscription --noacl -D

don't seem to work. I'm just getting a normal error log specified with "-l tvhclang3.log"

I'm not even getting warning like specified in the tvheadend documentation page for debugging:

==16673==WARNING: Trying to symbolize code, but external symbolizer is not initialized! --> not in my log

Any hints on how to generate the proper error that you would need?

#3

Updated by john beton about 6 years ago

I also tried this but no avail:

ASAN_OPTIONS=symbolize=1 ASAN_SYMBOLIZER_PATH=/usr/lib/llvm-3.8/bin:$PATH /home/probook/tvheadend/build.linux/tvheadend -l tvhclang4.log --trace satip,linuxdvb,subscription,en50221,dvbcam --noacl -D

#4

Updated by john beton about 6 years ago

running this now:

ASAN_OPTIONS=symbolize=1 ASAN_SYMBOLIZER_PATH=$(which llvm-symbolizer) /home/probook/tvheadend/build.linux/tvheadend -l tvhclangfinal.log --trace satip,linuxdvb,subscription --noacl -D

I don't get any error starting tvheadend with this command so I guess it's ok to run it like this? The problem I have is that the tuner becomes unresponsive after a while. Sometimes this happens when memory reaches 59%, sometimes only 18%. If I restart tvheadend, I can start over but it's just waiting for another lockup.

2018-11-04 22:44:46.080 [WARNING] subscription: 0002: service instance is bad, reason: No access
2018-11-04 22:44:48.080 [ NOTICE] subscription : 0002: No input source available for subscription "SAT>IP Slave/TN/314MHz/EUROSPORT HD" to service "TN/314MHz/EUROSPORT HD" in mux "314MHz in TN"

So, I'm not sure if any "useful" errors are being generated. It's really not a tuner issue or driver/firmware issue. My device is very stable with tvheadend when streaming FTA channels.

#5

Updated by john beton about 6 years ago

Same issue on debian 8, debian 9, Ubuntu 18.10

I still can't figure out how to get those clang debug logs? I perform everything as described like here:

https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption

When am I supposed to see these kind of messages? (==27911==ERROR: AddressSanitizer: ) ? When tvheadend crashes or during the memory leakage itself?

Because the thing is that tvheadend doesn't really crash. It just drops connection to the tuner and memory usage stalls at a certain %. Are

Can somebody perform a similar test with latest git? Just stream a scrambled channel with the satip server to a client (VLC, DVBViewer,...)

I went back a few months and the problem is also present in the code on 20th of june 2018. This is the furthest I went back yet.

https://github.com/tvheadend/tvheadend/tree/5750826be0cefb1069a08d90608147565954a8b3

Is there another way to debug this issue? Without clang or Valgrind?

#6

Updated by Jaroslav Kysela almost 6 years ago

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

Applied in changeset commit:tvheadend|905bf283a2fee9348403c95dc9ad3ca4a9c46929.

#7

Updated by john beton almost 6 years ago

Hello Jaroslav,

I have recompiled tvheadend with latest commit and now tvheadend cannot descramble channels anymore via satip. I'm currently testing with a local cccam connection.

No input source available for subscription "SAT>IP Slave/TN/306MHz/Eurosport HD" to service "TN/306MHz/Eurosport HD" in mux "306MHz in TN"

I have attached a log with --trace satip,linuxdvb,subscription,cccam,descrambler,service,mpegts

Thanks for looking into this.

#8

Updated by Jaroslav Kysela almost 6 years ago

It was another issue. Try v4.3-1524-ga093b4371 .

#9

Updated by john beton almost 6 years ago

Hello Jaroslav,

The memory issue seems solved. It stays stable around 0.3% all the time. The only thing still happening is that the tuner is lost after a while when serving a scrambled channel.

The logs indicate that there is 1 Continuity counter error and it is killing the tuner connection access..

2018-11-08 22:41:28.551 [WARNING] TS: TN/306MHz/vtm HD: H264 #3501 Continuity counter error (total 1)
2018-11-08 22:41:28.551 [WARNING] TS: TN/306MHz/vtm HD: MPEG2AUDIO
#3502 Continuity counter error (total 1)
2018-11-08 22:41:28.567 [WARNING] TS: TN/306MHz/vtm HD: TELETEXT @ #3503 Continuity counter error (total 1)
2018-11-08 22:41:29.808 [WARNING] subscription: 0002: service instance is bad, reason: No access

I have attached a log with --trace satip,linuxdvb,subscription,cccam,descrambler,service,mpegts. Also 2 screenshots of the DVBViewer source filter. You can clearly notice 1 discontinuity in the scrambled channel stream. Normally this shouldn't cause the stream to stop, right? I also tried streaming an FTA channel and this stays stable for several hours with not a single discontinuity.

If you need more traces, please let me know how I can help.

#10

Updated by Ricardo Rocha almost 6 years ago

John Törnblom beton give a look on #4992 i had the same issue... the simptons are 100% equal... on my case thats because a strange exchange of keys between oscam and tvheadend!

so maybe the trouble is the same!

#11

Updated by Jaroslav Kysela almost 6 years ago

2018-11-08 22:38:58.778 [  TRACE]:descrambler: Obtained CSA keys 77ACD1F4C6E88533:34BDB0A12F0EA3E0 pid 0000 from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:39:28.776 [  TRACE]:descrambler: Obtained CSA keys 77ACD1F4C6E88533:67F487E2C51215EC pid 0000 from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:39:58.778 [  TRACE]:descrambler: Obtained CSA keys DA80A600D157E911:67F487E2C51215EC pid 0000 from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:40:28.768 [  TRACE]:descrambler: Obtained CSA keys DA80A600D157E911:B3C56BE36AF10560 pid 0000 from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:41:28.781 [  DEBUG]:cccam: 192.168.1.7:2222: Obtained DES keys for service "vtm HD" in 184 ms, from cccam-192.168.1.7:2222-1801
2018-11-08 22:41:28.781 [  DEBUG]:descrambler: Obtained CSA keys from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:41:28.781 [  TRACE]:descrambler: Obtained CSA keys 461F3DA2AE086016:3C6CB75FB5F4B55E pid 0000 from cccam-192.168.1.7:2222-1801 for service "vtm HD" 
2018-11-08 22:40:56.578 [  TRACE]:cccam: 192.168.1.7:2222: del card 0000006F message received
2018-11-08 22:40:56.578 [   INFO]:cccam: 192.168.1.7:2222: card ID:0000006f CAID:1801 with 3 providers removed
2018-11-08 22:40:56.578 [  TRACE]:descrambler: close emm caid 1801 (6145) pid 044D (1101) - direct
2018-11-08 22:40:56.578 [  TRACE]:mpegts: table: mux 0x558b6b5b6870 destroy emm 00/00 (0) pid 044D (1101)
2018-11-08 22:40:56.578 [  TRACE]:descrambler: mux 0x558b6b5b6870 close pid 044D (1101) (flags 0x0000) for 0x7fb340002320
....
2018-11-08 22:40:56.579 [  TRACE]:cccam: 192.168.1.7:2222: add card message received
2018-11-08 22:40:56.579 [   INFO]:cccam: 192.168.1.7:2222: Connected as user user1 to a NagraVision-card-00000071 [CAID:1801] with 3 providers
2018-11-08 22:40:56.579 [  DEBUG]:cccam: 192.168.1.7:2222: Providers: ID:00000071 CAID:1801:[0x007611,0x000000,0x007711]
....
2018-11-08 22:40:56.590 [  DEBUG]:mpegts: 306MHz in TN - close PID 044D (1101) [16/0x7fb324005b60]

The CA was removed and added again by cccam, but tvh stops to send the ECM requests after this.

Try v4.3-1526-g42fb10e77 .

Ricardo - I don't think that's a similar issue. It's cccam specific.

#12

Updated by Jaroslav Kysela almost 6 years ago

And again - another issue - create a new bug next time.

#13

Updated by Ricardo Rocha almost 6 years ago

Hi Jaroslav, i just commented because the simptons are equal... sorry!

and thanks!

#14

Updated by john beton almost 6 years ago

The initial problem with the unavailable slaves has been solved. I have not found the time to test the CA problem.

Thank you Jaroslav.

Also available in: Atom PDF