Bug #5314
Memory leak in sat>ip server with scrambled channels
100%
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
History
Updated by Jaroslav Kysela about 6 years ago
Updated by 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
Updated by john beton about 6 years ago
Updated by 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?
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
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.
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?
Updated by Jaroslav Kysela about 6 years ago
- Status changed from New to Fixed
- % Done changed from 0 to 100
Applied in changeset commit:tvheadend|905bf283a2fee9348403c95dc9ad3ca4a9c46929.
Updated by john beton about 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.
Updated by john beton about 6 years ago
- File tvh8scrambled.log tvh8scrambled.log added
- File FTA.png FTA.png added
- File SCRAMBLED.png SCRAMBLED.png added
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) #3502 Continuity counter error (total 1)
2018-11-08 22:41:28.551 [WARNING] TS: TN/306MHz/vtm HD: MPEG2AUDIO
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.
Updated by Ricardo Rocha about 6 years ago
Updated by 
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!
Updated by Jaroslav Kysela about 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.
Updated by Jaroslav Kysela about 6 years ago
And again - another issue - create a new bug next time.
Updated by Ricardo Rocha about 6 years ago
Hi Jaroslav, i just commented because the simptons are equal... sorry!
and thanks!
Updated by john beton about 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.