Tvheadend

It looks like a memory corruption. https://tvheadend.org/projects/tvheadend/wiki/Debugging#Memory-leaks-or-corruption

Yeah, I'll probably do some memory analysis when I have time. The crash only happens when I power off a client in an unclean manner.

But it strikes me that the crash happens in tvhcsa.c in code that looks like BISS decryptor, and every time it does happen, the client was actually subscribed to a channel decrypted via CWC client (newcamd). I do have channels using BISS DES keys, but as these are not used on the channel the client was subscribed to, isn't it weird that it's this code that causes a crash?

Or is the code in tvhcsa.c used even for channels decrypted using a CWC client? I'm a little confused by seeing odd and even keys in there.

Haven't yet had time to investigate further, but there must be a really nasty bug somewhere in there. It crashes quite often:

Aug 26 02:09:35 [tvheadend] TS: Astra 23.5E/11934V/Nick Jr Czech: H264 @ #6410 Continuity counter error (total 5064)
Aug 26 02:09:35 [tvheadend] TS: Astra 23.5E/11934V/Nick Jr Czech: MPEG2AUDIO @ #6420 Continuity counter error (total 783)
Aug 26 02:09:35 [tvheadend] TS: Astra 23.5E/11934V/Nick Jr Czech: MPEG2AUDIO @ #6421 Continuity counter error (total 819)
Aug 26 02:09:35 [tvheadend] CRASH: Signal: 11 in PRG: /usr/bin/tvheadend (4.3-334~g7db25fab0-dirty) [e7b7bd3cfe1e41e56057ce6290c7c6347cd9caae] CWD: /  
Aug 26 02:09:35 [tvheadend] CRASH: Fault address 0x7f5428b46390 (Access error)
Aug 26 02:09:35 [tvheadend] CRASH: Loaded libraries: linux-vdso.so.1 /usr/lib64/libdvbcsa.so.1 /usr/lib64/libdvben50221.so /usr/lib64/libdvbapi.so /usr/lib64/libucsi.so /usr/lib64/libssl.so.1.0.0 /usr/lib64/libcr
ypto.so.1.0.0 /lib64/libz.so.1 /usr/lib64/libpcre2-8.so.0 /usr/lib64/libavahi-common.so.3 /usr/lib64/libavahi-client.so.3 /usr/lib64/libavfilter.so.6 /usr/lib64/libswresample.so.2 /usr/lib64/libavresample.so.3 /u
sr/lib64/libswscale.so.4 /usr/lib64/libavformat.so.57 /usr/lib64/libavcodec.so.57 /usr/lib64/libavutil.so.55 /usr/lib64/libdbus-1.so.3 /lib64/libdl.so.2 /lib64/libpthread.so.0 /lib64/libm.so.6 /lib64/librt.so.1 /
lib64/libc.so.6 /usr/lib64/libpostproc.so.54 /usr/lib64/libva.so.1 /lib64/libbz2.so.1 /usr/lib64/libxvidcore.so.4 /usr/lib64/libx265.so.130 /usr/lib64/libx264.so.142 /usr/lib64/libvpx.so.4 /usr/lib64/libvorbisenc
.so.2 /usr/lib64/libvorbis.so.0 /usr/lib64/libtheoraenc.so.1 /usr/lib64/libtheoradec.so.1 /usr/lib64/libopus.so.0 /usr/lib64/libmp3lame.so.0 /usr/lib64/libfdk-aac.so.1 /usr/lib64/libcrystalhd.so.3 /usr/l
Aug 26 02:09:35 [tvheadend] CRASH: Register dump [23]: 0000000085d314dd00007f54280044b0ea05f505b51db445236b9aa6ebcac759ac14964a4d03ab6aeb50e816d6ca1fcca58b7377b33627b37511f6a01ba19fec00007f54280040b00000000000000
08b30af59176de4aad8000000000000008b00007f541fdfca00000000000000008b00007f5428b4630500007f541fdfc51800007f5451f5f1cc0000000000010283002b0000000000330000000000000006000000000000000efffffffe7ffbba1100007f5428b46390
Aug 26 02:09:35 [tvheadend] CRASH: STACKTRACE
Aug 26 02:09:35 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/trap.c:148 0x556fe461a56d 0x556fe4489000
Aug 26 02:09:35 [tvheadend] CRASH: ??:0 0x7f544dd0cbf0 0x7f544dcf9000
Aug 26 02:09:35 [tvheadend] CRASH: dvbcsa_bs_stream_transpose_out+0x2dc  (/usr/lib64/libdvbcsa.so.1)
Aug 26 02:09:35 [tvheadend] CRASH: dvbcsa_bs_stream_cipher_batch+0x31cb  (/usr/lib64/libdvbcsa.so.1)
Aug 26 02:09:35 [tvheadend] CRASH: dvbcsa_bs_decrypt+0x16  (/usr/lib64/libdvbcsa.so.1)
Aug 26 02:09:35 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/tvhcsa.c:84 0x556fe46e1c1d 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/tvhcsa.c:178 0x556fe46e1dd2 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/descrambler.c:1105 0x556fe4685896 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/tsdemux.c:338 0x556fe468efa1 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_input.c:1332 0x556fe468c455 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/wrappers.c:161 0x556fe45df765 0x556fe4489000
Aug 26 02:09:36 [tvheadend] CRASH: ??:0 0x7f544dd006c7 0x7f544dcf9000
Aug 26 02:09:36 [tvheadend] CRASH: clone+0x3f  (/lib64/libc.so.6)

And yet another crash backtrace, this time hinting at memory corruption or something. Latest Git.

#6  0x00007f0006ec4fb0 in raise () from /lib64/libc.so.6
#7  0x00007f0006ec6b07 in abort () from /lib64/libc.so.6
#8  0x00007f0006f0b8e7 in __libc_message () from /lib64/libc.so.6
#9  0x00007f0006f13328 in malloc_printerr () from /lib64/libc.so.6
#10 0x00007f0006f15254 in _int_free () from /lib64/libc.so.6
#11 0x000055e2d2f078ca in tvhcsa_destroy (csa=csa@entry=0x7effcc03d1d0) at src/descrambler/tvhcsa.c:320
#12 0x000055e2d2ea1e8c in descrambler_service_stop (t=<optimized out>) at src/descrambler/descrambler.c:427
#13 0x000055e2d2e1c73b in service_stop (t=0x55e2d8b899d0) at src/service.c:380
#14 0x000055e2d2e19ed2 in subscription_unlink_service0 (resched=0, reason=<optimized out>, s=<optimized out>) at src/subscriptions.c:165
#15 subscription_unlink_service (s=<optimized out>, reason=<optimized out>) at src/subscriptions.c:172
#16 0x000055e2d2e1c7d0 in service_remove_subscriber (t=<optimized out>, s=<optimized out>, reason=<optimized out>) at src/service.c:417
#17 0x000055e2d2e1a240 in subscription_unsubscribe (s=0x55e2d2e1c73b <service_stop+43>, s@entry=0x7eff58035fa0, flags=flags@entry=2) at src/subscriptions.c:729
#18 0x000055e2d2e20bd9 in htsp_subscription_destroy (htsp=0x7efff33f8780, hs=0x7eff580565b0) at src/htsp_server.c:378
#19 0x000055e2d2e237c6 in htsp_method_unsubscribe (htsp=0x7efff33f8780, in=0x7effc0033e20) at src/htsp_server.c:2603
#20 0x000055e2d2e24b29 in htsp_read_loop (htsp=0x7efff33f8780) at src/htsp_server.c:3271
#21 htsp_serve (fd=46, opaque=0x7eff7c002098, source=<optimized out>, self=<optimized out>) at src/htsp_server.c:3409
#22 0x000055e2d2dfa5a2 in tcp_server_start (aux=0x7eff7c002070) at src/tcp.c:709
#23 0x000055e2d2df5a38 in thread_wrapper (p=0x7eff7c000f90) at src/wrappers.c:162
#24 0x00007f00077b292a in start_thread () from /lib64/libpthread.so.0
#25 0x00007f0006f914ef in clone () from /lib64/libc.so.6

All in all, my impression is that when unsubscribing from a TV channel, the HTSP and MPEG TS input threads don't synchronize properly and sometimes use the memory after free.

Use valgind to detect where the wrong memory access occurs.

I've tried using Valgrind, but using Valgrind and receiving encrypted channels is next to impossible. It is too slow and playback breaks too early (with EOVERFLOW when receiving data from the tuner).

I've had yet another crash (w/o Valgrind) and it seems to be the same problem:

Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/cwc.c:645 0x5614d9ff5837 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/cclient.c:807 0x5614d9ff0f02 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/descrambler.c:1307 0x5614d9f897e9 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_table.c:103 0x5614d9f9fa7e 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/dvb_psi_lib.c:128 (discriminator 4) 0x5614d9f97a0b 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/dvb_psi_lib.c:173 0x5614d9f97c74 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_input.c:1264 (discriminator 3) 0x5614d9f904eb 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_input.c:1624 0x5614d9f906d0 0x5614d9d7e000
Jan 11 20:31:03 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/wrappers.c:181 0x5614d9edccc8 0x5614d9d7e000

This happens two seconds after:

Jan 11 20:31:01 [tvheadend] subscription: 002C: "fd00:1::ba27:ebff:fe2d:97b7 [  | Kodi Media Center ]" unsubscribing from "Nick Jr Czech", hostname="fd00:1::ba27:ebff:fe2d:97b7", username="fd00:1::ba27:ebff:fe2d:97b7", client="Kodi Media Center" 

My impression is that the unsubscribe event (from htsp_read_loop) frees the memory structures for decryption, which could still be ongoing in the mpegts_input thread. I find the case quite clear, but I don't know how this was intended to work.

There is no code on line 645 in cwc.c and it looks like a new issue. There are mutexes which protects (serializes) the data operations. So in the service unsubscribe procedure, the associated descrambler is removed. Could you try this additional mutex code?

diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index 98ea230d2..9d1abd91d 100644
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -416,10 +416,12 @@ descrambler_service_stop ( service_t *t )

   while ((td = LIST_FIRST(&t->s_descramblers)) != NULL)
     td->td_stop(td);
+  pthread_mutex_lock(&t->s_stream_mutex);
   t->s_descramble = NULL;
   t->s_descrambler = NULL;
   p = t->s_descramble_info;
   t->s_descramble_info = NULL;
+  pthread_mutex_unlock(&t->s_stream_mutex);
   free(p);
   if (dr) {
     for (i = 0; i < DESCRAMBLER_MAX_KEYS; i++) {

Hmm, yes, this is quite possibly something new. I've just had this very crash happen again TWICE even after your changes (and again it mentions line 645 where there is no code) even without watching any channels.

Jan 11 21:25:38 [tvheadend] mpegts: 12344H in Astra 23.5E - tuning on TurboSight TBS 6985 DVB-S/S2 #3 - napravo vpredu
Jan 11 21:25:38 [tvheadend] subscription: 002F: "epggrab" subscribing to mux "12344H", weight: 4, adapter: "TurboSight TBS 6985 DVB-S/S2 #3 - napravo vpredu", network: "Astra 23.5E", service: "Raw PID Subscription" 
Jan 11 21:25:38 [tvheadend] mpegts: 12109H in Astra 23.5E - tuning on TurboSight TBS 6985 DVB-S/S2 #0
Jan 11 21:25:39 [tvheadend] subscription: 0030: "epggrab" subscribing to mux "12109H", weight: 4, adapter: "TurboSight TBS 6985 DVB-S/S2 #0", network: "Astra 23.5E", service: "Raw PID Subscription" 
Jan 11 21:26:05 [tvheadend] cwc: 127.0.0.1:10006: Disconnected
Jan 11 21:26:05 [tvheadend] cwc: 127.0.0.1:10001: Disconnected
Jan 11 21:26:05 [tvheadend] cwc: 127.0.0.1:10006: Automatic connection attempt in 2 seconds
Jan 11 21:26:05 [tvheadend] cwc: 127.0.0.1:10001: Automatic connection attempt in 2 seconds
Jan 11 21:26:06 [tvheadend] cwc: localhost:10002: Disconnected
Jan 11 21:26:06 [tvheadend] cwc: localhost:10002: Automatic connection attempt in 2 seconds
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10006: Attemping to connect to server
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10001: Attemping to connect to server
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10001: Connected as user tvheadend to a NDS-card-00000000 [CAID:0963 : 00.00.00.00.03.1e.8d.44] with 1 provider
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10001: Will forward EMMs
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10006: Connected as user tvheadend to a Irdeto-card-00000000 [CAID:0624 : 00.00.00.00.10.0a.82.b5] with 5 providers
Jan 11 21:26:08 [tvheadend] cwc: 127.0.0.1:10006: Will forward EMMs
Jan 11 21:26:09 [tvheadend] subscription: 002F: "epggrab" unsubscribing
Jan 11 21:26:09 [tvheadend] cwc: localhost:10002: Attemping to connect to server
Jan 11 21:26:09 [tvheadend] cwc: localhost:10002: Connected as user tvheadend to a CryptoWorks ICE-card-00000000 [CAID:0d97 : 00.00.00.00.14.ba.5f.f0] with 5 providers
Jan 11 21:26:09 [tvheadend] cwc: localhost:10002: Will forward EMMs
Jan 11 21:26:10 [tvheadend] mpegts: 12070H in Astra 23.5E - tuning on TurboSight TBS 6985 DVB-S/S2 #3 - napravo vpredu
Jan 11 21:26:10 [tvheadend] subscription: 0033: "epggrab" subscribing to mux "12070H", weight: 4, adapter: "TurboSight TBS 6985 DVB-S/S2 #3 - napravo vpredu", network: "Astra 23.5E", service: "Raw PID Subscription" 
Jan 11 21:26:10 [tvheadend] CRASH: Signal: 11 in PRG: /usr/bin/tvheadend (4.3-933~g914919f15-dirty) [09c2796c2c3701628db2ef92ab779bf985c9ffcd] CWD: /  
Jan 11 21:26:10 [tvheadend] CRASH: Fault address 0x20 (Address not mapped)
Jan 11 21:26:10 [tvheadend] CRASH: Loaded libraries: linux-vdso.so.1 /usr/lib64/libdvbcsa.so.1 /usr/lib64/libssl.so.1.0.0 /usr/lib64/libcrypto.so.1.0.0 /lib64/libz.so.1 /usr/lib64/libpcre2-8.so.0 /usr/lib64/liburiparser.so.1 /usr/lib64/libavahi-common.so.3 /usr/lib64/libavahi-client.so.3 /usr/lib64/libavfilter.so.6 /usr/lib64/libswresample.so.2 /usr/lib64/libavresample.so.3 /usr/lib64/libswscale.so.4 /usr/lib64/libavformat.so.57 /usr/lib64/libavcodec.so.57 /usr/lib64/libavutil.so.55 /usr/lib64/libva.so.2 /usr/lib64/libva-x11.so.2 /usr/lib64/libva-drm.so.2 /usr/lib64/libdbus-1.so.3 /lib64/libdl.so.2 /lib64/libpthread.so.0 /lib64/libm.so.6 /lib64/librt.so.1 /lib64/libc.so.6 /usr/lib64/libpostproc.so.54 /usr/lib64/libgnutls.so.30 /lib64/libbz2.so.1 /usr/lib64/libcrystalhd.so.3 /usr/lib64/libxvidcore.so.4 /usr/lib64/libx265.so.146 /usr/lib64/libx264.so.142 /usr/lib64/libvpx.so.4 /usr/lib64/libvorbisenc.so.2 /usr/lib64/libvorbis.so.0 /usr/lib64/libtheoraenc.so.1 /usr/lib64/libtheoradec.so.1 /usr/lib64/libopus.so.0 /usr/lib64/libmp3lame.so.0
Jan 11 21:26:10 [tvheadend] CRASH: Register dump [23]: 00007f695c00ce58000000000000000000007f698f9fb7d000007f698f9fb468000000000000003300005645aeed2fe000005645aeed314000007f695c00cdf000005645aeed2fe0000000000000000000007f695c00ce5800007f69a0000da000007f69a0000da00000000000000033000000000000000000007f698f9fb51800005645ad7198670000000000010206002b0000000000330000000000000004000000000000000efffffffe7ffbba110000000000000020
Jan 11 21:26:10 [tvheadend] CRASH: STACKTRACE
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/trap.c:164 0x5645ad63fa4d 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: ??:0 0x7f69c2c38170 0x7f69c2c24000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/cwc.c:645 0x5645ad719867 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/cclient.c:807 0x5645ad714f32 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/descrambler/descrambler.c:1309 0x5645ad6ad7e9 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_table.c:103 0x5645ad6c3aae 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/dvb_psi_lib.c:128 (discriminator 4) 0x5645ad6bba3b 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/dvb_psi_lib.c:173 0x5645ad6bbca4 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_input.c:1264 (discriminator 3) 0x5645ad6b451b 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/input/mpegts/mpegts_input.c:1624 0x5645ad6b4700 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: /home/lubos/Projects/tvheadend/src/wrappers.c:181 0x5645ad600cc8 0x5645ad4a2000
Jan 11 21:26:10 [tvheadend] CRASH: ??:0 0x7f69c2c2b92a 0x7f69c2c24000
Jan 11 21:26:10 [tvheadend] CRASH: clone+0x3f  (/lib64/libc.so.6)

Compile tvh with 'gcc -O0' (use '--enable-ccdebug' argument for tvh's configure script). Perhaps, it will give us more clue. Also, you may run tvh in gdb (or attach gdb to tvh) to do gdb's backtrace and variable inspection.

I probably see it. Disable EMM for this moment.

Yep:

cwc_send_emm (cc=0x555555c656e0, ct=0x0, pcard=0x7fffd8000da0, provid=0, data=0x7fff9c019888 "\202p0", len=51) at src/descrambler/cwc.c:647
647       uint16_t sid = t->s_dvb_service_id;
(gdb) p t
Cannot access memory at address 0x20

I pushed a fix to github right now.