Segfault in decrypt_packets due to bad driver

[epienbroek]

Hi,

I've noticed that FFdecsawrapper segfaults quite frequently on my environment. The crashes happen when FFdecsawrapper is running for a couple of hours.

I'm running dvbloopback+FFdecsawrapper+OSCAM+MythTV here using a TechnoTrend CT2-4400 USB device which is connected to the Ziggo DVB-C network. The operating system is CentOS 7 with kernel 3.10.0-229.20.1.el7.centos.plus.x86_64 and a git checkout of the v4l media_tree (with dvbloopback) from November 1 2015. FFdecsawrapper is compiled using PARALLEL_MODE=PARALLEL_128_SSE2. FFdecsawrapper is started with the following command line options: ./ffdecsawrapper -j 0:1 --sid-allpid --cam-budget --pidfile /run/ffdecsawrapper.pid --cam-dir /etc/camfiles

Because of the frequent crashes I decided to try to debug using Valgrind. There are multiple areas where Valgrind reports about (for one I already have a fix ready) but in this issue I'm limiting to the final segfault for now. To get more valuable/reliable backtraces I removed the compiler flag -fomit-frame-pointer and added the compiler flag -g in the config.mak file.

Here's the Valgrind output about the failures which eventually lead to the segfault:

==20195== Thread 12:
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EA9F: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EAA7: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EAAF: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EAB8: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EAC0: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Use of uninitialised value of size 8
==20195==    at 0x48EA73: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195== 
==20195== Invalid read of size 8
==20195==    at 0x48EA73: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)
==20195==  Address 0x3fbfff25c10fd55b is not stack'd, malloc'd or (recently) free'd
==20195== 
==20195== 
==20195== Process terminating with default action of signal 11 (SIGSEGV): dumping core
==20195==  General Protection Fault
==20195==    at 0x48EA73: decrypt_packets(void*, unsigned char**) (FFdecsa.c:840)
==20195==    by 0x4722DD: process_ts(csastruct*, unsigned char*, unsigned int, int) (plugin_ffdecsa.c:327)
==20195==    by 0x472C70: process_ffd(msg*, unsigned int) (plugin_ffdecsa.c:512)
==20195==    by 0x468FAA: msg_loop(void*) (msg_passing.c:118)
==20195==    by 0x4E3CDC4: start_thread (pthread_create.c:308)
==20195==    by 0x5F8521C: clone (clone.S:113)

The code in question (FFdecsa.c:840) is:

  for(g=0;g<alive[iter];g++){
    COPY_8_BY(ib+8*g,encp[g]);          <<<< segfault happens here
  }

As can be observed in the output above it looks like the for-loop gets iterated 7 times using unitialized data and one time doing an invalid read.

I'm still doing research here but I decided to share my findings so far and perhaps you can assist in researching the root cause

[bas-t]

Hi, I have second thoughts about your PR. Please check wether or not your kernel is compiled with CONFIG_I2C_MUX=m si2168 needs it. Furthermore, is that V4L checkout you used in a known good state for your dvb adapter? Cheers, Tycho.

[epienbroek]

Which PR do you mean exactly? This one (which is not a GitHub PR, but an GitHub issue) or PR #6 which I submitted yesterday? If it's about #6 I suggest we keep the discussion there because I think it does resolve a valid bug (even with buggy DVB input).

Back to your other questions about this issue:

I2C_MUX support in enabled in the kernel which I'm currently running:

# grep I2C_MUX /boot/config-`uname -r`
CONFIG_I2C_MUX=m
CONFIG_I2C_MUX_GPIO=m
CONFIG_I2C_MUX_PCA9541=m
CONFIG_I2C_MUX_PCA954x=m
# modinfo i2c_mux
filename:       /lib/modules/3.10.0-229.20.1.el7.centos.plus.x86_64/kernel/drivers/i2c/i2c-mux.ko
license:        GPL v2
description:    I2C driver for multiplexed I2C busses
author:         Rodolfo Giometti <giometti@linux.it>
rhelversion:    7.1
srcversion:     68ED3055C47D6EE478EEF35
depends:        i2c-core
intree:         Y
vermagic:       3.10.0-229.20.1.el7.centos.plus.x86_64 SMP mod_unload modversions 
signer:         CentOS Linux kernel signing key
sig_key:        F0:D3:FF:BD:08:9B:CE:40:9F:2E:A8:FD:2B:B1:EF:25:DC:DA:BD:35
sig_hashalgo:   sha256

According to http://linuxtv.org/wiki/index.php/TechnoTrend_TT-TVStick_CT2-4400 the DVB adapter I'm using should be fuly supported as of kernel 3.19 and in media_tree. The most recent change in that wiki page was on August 3 2015 and the media_tree checkout I'm using is from November 1 2015 so I guess it should be recent enough.

For reference, here's the list of DVB-related modules which are currently loaded:

# lsmod | grep dvb
dvbloopback            24223  47 
dvb_usb_dvbsky         18538  0 
dvb_usb_v2             36107  1 dvb_usb_dvbsky
rc_core                27417  4 rc_tt_1500,dvb_usb_v2,dvb_usb_dvbsky
m88ds3103              24724  1 dvb_usb_dvbsky
dvb_core              126384  4 dvb_usb_v2,m88ds3103,dvb_usb_dvbsky,dvbloopback
i2c_core               40499  11 drm,i2c_mux,regmap_i2c,drm_kms_helper,mgag200,i2c_algo_bit,si2157,si2168,dvb_usb_v2,m88ds3103,dvb_usb_dvbsky

I do have to notice that I manually pinned to a specific revision of the media_build and media_tree which I had to do because the most recent revision failed to compile at the time I attempted to built everything (nov 18 2015). For media_build I pinned to http://git.linuxtv.org//media_build.git/commit/?id=0d0e21e9487d0f114776825cf6c615fd146d0b09 and for media_tree I pinned to http://git.linuxtv.org//media_tree.git/commit/?id=6a13feb9c82803e2b815eca72fa7a9f5561d7861

If you think it helps I could retry again with the most recent media_tree

[epienbroek]

Apparently the most recent media_tree can't be built for some reason. The dvbloopback configure script fails with a fatal error:

# ./configure --ffdecsawrapper=no --v4l=yes 

Your local clone is clean and up-to-date

Going to clone the v4l buildsystem of choise.

Cloning into 'media_build'...
remote: Counting objects: 3170, done.
remote: Compressing objects: 100% (896/896), done.
remote: Total 3170 (delta 2248), reused 3142 (delta 2233)
Receiving objects: 100% (3170/3170), 576.97 KiB | 0 bytes/s, done.
Resolving deltas: 100% (2248/2248), done.
Cloning into 'media_tree'...
remote: Counting objects: 56094, done.
remote: Compressing objects: 100% (53336/53336), done.
remote: Total 56094 (delta 4559), reused 26695 (delta 1957)
Receiving objects: 100% (56094/56094), 149.16 MiB | 5.56 MiB/s, done.
Resolving deltas: 100% (4559/4559), done.
Checking out files: 100% (52919/52919), done.

Mauro may have decided that "MEDIA_CONTROLLER_DVB" is not broken anymore.
Review the situation and act.
Aborting...

I'll workaround this for now.

For reference: it fails on this piece of code:

  if [ "x$v4l_opt" = "xyes" ];then
    git clone git://linuxtv.org/media_build.git || die "Error(s) while fetching v4l build system"
    git clone --depth=1 git://linuxtv.org/media_tree.git || die "Error(s) while fetching v4l source tree"
    if ! cat media_tree/drivers/media/Kconfig | grep "BROKEN" > /dev/null 2>&1; then
      echo "
Mauro may have decided that \"MEDIA_CONTROLLER_DVB\" is not broken anymore.
Review the situation and act.
Aborting...
"
      env_clean
      exit 0
    fi

The command cat media_tree/drivers/media/Kconfig | grep "BROKEN" returns no output and exit code 1 on my environment

[bas-t]

That's because when a kernel, or v4l tree for that matter, was compiled with MEDIA_CONTROLLER_DVB enabled, it was a certain road to desaster. I'm lacking time to review the current situation right now, but thanks for the heads-up.

Op 14-02-16 om 15:16 schreef Erik van Pienbroek:

Apparently the most recent media_tree can't be built for some reason. The dvbloopback configure script fails with a fatal error:

|# ./configure --ffdecsawrapper=no --v4l=yes Your local clone is clean and up-to-date Going to clone the v4l buildsystem of choise. Cloning into 'media_build'... remote: Counting objects: 3170, done. remote: Compressing objects: 100% (896/896), done. remote: Total 3170 (delta 2248), reused 3142 (delta 2233) Receiving objects: 100% (3170/3170), 576.97 KiB | 0 bytes/s, done. Resolving deltas: 100% (2248/2248), done. Cloning into 'media_tree'... remote: Counting objects: 56094, done. remote: Compressing objects: 100% (53336/53336), done. remote: Total 56094 (delta 4559), reused 26695 (delta 1957) Receiving objects: 100% (56094/56094), 149.16 MiB | 5.56 MiB/s, done. Resolving deltas: 100% (4559/4559), done. Checking out files: 100% (52919/52919), done. Mauro may have decided that "MEDIA_CONTROLLER_DVB" is not broken anymore. Review the situation and act. Aborting... |

I'll workaround this for now.

For reference: it fails on this piece of code:

|if [ "x$v4l_opt" = "xyes" ];then git clone git://linuxtv.org/media_build.git || die "Error(s) while fetching v4l build system" git clone --depth=1 git://linuxtv.org/media_tree.git || die "Error(s) while fetching v4l source tree" if ! cat media_tree/drivers/media/Kconfig | grep "BROKEN" > /dev/null 2>&1; then echo " Mauro may have decided that \"MEDIA_CONTROLLER_DVB\" is not broken anymore. Review the situation and act. Aborting... " env_clean exit 0 fi |

The command |cat media_tree/drivers/media/Kconfig | grep "BROKEN"| returns no output and exit code 1 on my environment

— Reply to this email directly or view it on GitHub https://github.com/bas-t/descrambler/issues/5#issuecomment-183896140.

[epienbroek]

But are you sure that the check in the ./configure script is correct for that? Right now it bails out when none of the options in media_tree/drivers/media/Kconfig are marked as 'BROKEN'. I would expect that it would only bail out when any of the options in that file are marked as 'BROKEN'.

Anyway, I just looked at the upstream git logs and the 'BROKEN' mark was apparently removed from that file recently: http://git.linuxtv.org/media_tree.git/commit/drivers/media/Kconfig?id=21a0654200f24208aadd7bdc80fcdec65d2eb64b

[bas-t]

I just pushed a workaround for this. You may want to try again. Mind you, yesterdays state of media_build was mostly broken for older kernels. (but it might be fixed by now)

Op 14-02-16 om 15:33 schreef Erik van Pienbroek:

But are you sure that the check in the ./configure script is correct for that? Right now it bails out when none of the options in media_tree/drivers/media/Kconfig are marked as 'BROKEN'. I would expect that it would only bail out when any of the options in that file are marked as 'BROKEN'.

Anyway, I just looked at the upstream git logs and the 'BROKEN' mark was apparently removed from that file recently: http://git.linuxtv.org/media_tree.git/commit/drivers/media/Kconfig?id=21a0654200f24208aadd7bdc80fcdec65d2eb64b

— Reply to this email directly or view it on GitHub https://github.com/bas-t/descrambler/issues/5#issuecomment-183901117.

[epienbroek]

I just managed to get everything built using the latest media_tree. Now we have to wait for the segfault to show up again.

Next to the MEDIA_CONTROLLER_DVB change mentioned earlier I also had to apply two additional changes in the dvbloopback git repo.

The first one is needed due to http://git.linuxtv.org/media_build.git/commit/?id=582c0f0475e568ea074aefc66ded0d471b843fbc:

--- a/v4l-make-install.patch
+++ b/v4l-make-install.patch
@@ -12,7 +12,7 @@
  #################################################
  # installation invocation rules

--modules_install install:: media-install firmware_install mm-install
+-modules_install install:: mm-install media-install firmware_install
 -
 -remove rminstall:: media-rminstall
 +modules_install install:: rminstall firmware_install

The second one is needed due to http://git.linuxtv.org/media_tree.git/commit/?id=df2f94e563edcbcb4b8652d05a3789d03b395366 where the number of arguments in the dvb_register_device function was changed:

--- a/dvbloopback/dvb_loopback.c
+++ b/dvbloopback/dvb_loopback.c
@@ -997,7 +997,7 @@ static int create_lb_dev(struct dvblb *dvblb, int dev_idx, int type)

 // create loopback device (will be frontend0)
        ret = dvb_register_device(&dvblb->adapter, &lbdev->lb_dev,
-                           &dvbdev_looped, lbdev, type);
+                           &dvbdev_looped, lbdev, type, 0);
        if (ret != 0) {
                info("error registering device adapter%d",
                     dvblb->adapter.num);
@@ -1005,7 +1005,7 @@ static int create_lb_dev(struct dvblb *dvblb, int dev_idx, int type)
        }
 // create userspace device (will be frontend1)
        ret = dvb_register_device(&dvblb->adapter, &lbdev->user_dev,
-                           &dvbdev_userspace, lbdev, type);
+                           &dvbdev_userspace, lbdev, type, 0);
        if (ret != 0) {
                info("error registering device adapter%d",
                     dvblb->adapter.num);

Here's already all V4L related dmesg output:

[    0.000000] Linux version 3.10.0-327.4.5.el7.centos.plus.x86_64 (builder@kbuilder.dev.centos.org) (gcc version 4.8.3 20140911 (Red Hat 4.8.3-9) (GCC) ) #1 SMP Tue Jan 26 02:04:11 UTC 2016
...
[   13.858549] media: module verification failed: signature and/or required key missing - tainting kernel
[   13.860251] media: Linux media interface: v0.10
[   13.928469] WARNING: You are using an experimental version of the media stack.
        As the driver is backported to an older kernel, it doesn't offer
        enough quality for its usage in production.
        Use it with care.
Latest git patches (needed if you report a bug to linux-media@vger.kernel.org):
        9b7f90e87c6cad2aed29ee248d1f86fd04a5f811 Add drivers, patch dvb-core.
        f7b4b54e63643b740c598e044874c4bffa0f04f2 [media] tvp5150: add HW input connectors support
[   13.966748] WARNING: You are using an experimental version of the media stack.
        As the driver is backported to an older kernel, it doesn't offer
        enough quality for its usage in production.
        Use it with care.
Latest git patches (needed if you report a bug to linux-media@vger.kernel.org):
        9b7f90e87c6cad2aed29ee248d1f86fd04a5f811 Add drivers, patch dvb-core.
        f7b4b54e63643b740c598e044874c4bffa0f04f2 [media] tvp5150: add HW input connectors support
...
[   14.178344] usb 3-1.5: dvb_usb_v2: found a 'TechnoTrend TVStick CT2-4400' in warm state
[   14.178383] usb 3-1.5: dvb_usb_v2: will pass the complete MPEG2 transport stream to the software demuxer
[   14.178393] DVB: registering new adapter (TechnoTrend TVStick CT2-4400)
[   14.178396] usb 3-1.5: media controller created
[   14.179830] usb 3-1.5: dvb_usb_v2: MAC address: bc:ea:2b:44:03:0b
[   14.180074] dvb_create_media_entity: media entity 'dvb-demux' registered.
[   14.509695] i2c i2c-1: Added multiplexed i2c bus 2
[   14.510961] si2168 1-0064: Silicon Labs Si2168 successfully attached
[   14.535490] si2157 2-0060: Silicon Labs Si2147/2148/2157/2158 successfully attached
[   14.536753] usb 3-1.5: DVB: registering adapter 0 frontend 0 (Silicon Labs Si2168)...
[   14.537981] dvb_create_media_entity: media entity 'Silicon Labs Si2168' registered.
...
[   14.697069] Registered IR keymap rc-tt-1500
[   14.697148] input: TechnoTrend TVStick CT2-4400 as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.5/rc/rc0/input2
[   14.697275] rc rc0: TechnoTrend TVStick CT2-4400 as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.5/rc/rc0
[   14.697277] usb 3-1.5: dvb_usb_v2: schedule remote query interval to 300 msecs
[   14.697279] usb 3-1.5: dvb_usb_v2: 'TechnoTrend TVStick CT2-4400' successfully initialized and connected
[   14.697297] usbcore: registered new interface driver dvb_usb_dvbsky
...
[   42.176632] dvbloopback: registering 1 adapters
[   42.176688] DVB: registering new adapter (DVB-LOOPBACK)
...
[   63.795005] si2168 1-0064: found a 'Silicon Labs Si2168-B40'
[   63.815162] si2168 1-0064: downloading firmware from file 'dvb-demod-si2168-b40-01.fw'
[   64.584987] si2168 1-0064: firmware version: 4.0.11
[   64.596519] si2157 2-0060: found a 'Silicon Labs Si2158-A20'
[   64.605859] si2157 2-0060: downloading firmware from file 'dvb-tuner-si2158-a20-01.fw'
[   65.666673] si2157 2-0060: firmware version: 2.1.6

[bas-t]

Thanks for the additional patches, I'll address this some time this week as a linux-4.5 diff

[bas-t]

quote But are you sure that the check in the ./configure script is correct for that? Right now it bails out when none of the options in media_tree/drivers/media/Kconfig are marked as 'BROKEN'. I would expect that it would only bail out when any of the options in that file are marked as 'BROKEN'. unquote

Yes, I'm absolutely sure. That is, at the time I did that, the only option marked as 'BROKEN' was that frigging MEDIA_CONTROLLER_DVB option. And I knew this piece of code would soon hit mainline. The check was just there so I'd notice whenever the expected change would occur. It was never intended to still be in the script well over a month after this 'broken' flag was removed.

However, I've been moving to a tvheadend/kodi setup. So I did not test any linux-4.5 related stuff yet. I'm not quite sure what I'll do next atm. Keep the tvheadend/kodi setup or revert to my previous setup (descrambler+dvbloopback+oscam+mythtv, just like yours)

[epienbroek]

Even with the latest V4L tree the segfault still remains (exact same position). Here's the last couple of lines from the FFdecsawrapper log file:

Feb 15 11:15:03.048 CSA: Removing csa for rb: 1
Feb 15 11:15:03.051 CHANNEL: Tuning frontend
Feb 15 11:15:03.051 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=0)
Feb 15 11:15:03.051 CAM(core.pids): 0: pids typ5=0836 typ5=0835 typ5=07dc typ5=07db typ5=07d1
Feb 15 11:15:03.051 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.051 CAM(core.pids): prgca: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 0836: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 0835: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07dc: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07db: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07d1: <empty>
Feb 15 11:15:03.051 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.051 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.051 CAM(core.pids): 0.1: pids on entry typ5=07d1 typ5=07db typ5=07dc typ5=0835 typ5=0836 typ5=0837
Feb 15 11:15:03.051 CAM(core.pids): 0.1: pids after delete typ5=07d1 typ5=07db typ5=07dc typ5=0835 typ5=0836
Feb 15 11:15:03.051 CAM(core.pids): 0.1: pids after add typ5=07d1 typ5=07db typ5=07dc typ5=0835 typ5=0836
Feb 15 11:15:03.051 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=0)
Feb 15 11:15:03.051 CAM(core.pids): 0: pids typ5=0835 typ5=07dc typ5=07db typ5=07d1
Feb 15 11:15:03.051 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.051 CAM(core.pids): prgca: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 0835: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07dc: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07db: <empty>
Feb 15 11:15:03.051 CAM(core.pids): pidca 07d1: <empty>
Feb 15 11:15:03.051 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.052 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids on entry typ5=07d1 typ5=07db typ5=07dc typ5=0835 typ5=0836
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after delete typ5=07d1 typ5=07db typ5=07dc typ5=0835
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after add typ5=07d1 typ5=07db typ5=07dc typ5=0835
Feb 15 11:15:03.052 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=0)
Feb 15 11:15:03.052 CAM(core.pids): 0: pids typ5=07dc typ5=07db typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.052 CAM(core.pids): prgca: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07dc: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07db: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07d1: <empty>
Feb 15 11:15:03.052 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.052 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids on entry typ5=07d1 typ5=07db typ5=07dc typ5=0835
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after delete typ5=07d1 typ5=07db typ5=07dc
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after add typ5=07d1 typ5=07db typ5=07dc
Feb 15 11:15:03.052 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=0)
Feb 15 11:15:03.052 CAM(core.pids): 0: pids typ5=07db typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.052 CAM(core.pids): prgca: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07db: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07d1: <empty>
Feb 15 11:15:03.052 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.052 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids on entry typ5=07d1 typ5=07db typ5=07dc
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after delete typ5=07d1 typ5=07db
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after add typ5=07d1 typ5=07db
Feb 15 11:15:03.052 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=0)
Feb 15 11:15:03.052 CAM(core.pids): 0: pids typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.052 CAM(core.pids): prgca: <empty>
Feb 15 11:15:03.052 CAM(core.pids): pidca 07d1: <empty>
Feb 15 11:15:03.052 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.052 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids on entry typ5=07d1 typ5=07db
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after delete typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after add typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): 0: update SID 19461 (zero=0 noshift=1)
Feb 15 11:15:03.052 CAM(core.pids): 0: SID=19461 zero=0 | sid=1/19461/0 zero=-/-/- idle=-/-/-
Feb 15 11:15:03.052 CAM(core.pids): 0: found handler for SID 19461 (0.1 idle=0 idx=1)
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids on entry typ5=07d1
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after delete
Feb 15 11:15:03.052 CAM(core.pids): 0.1: pids after add
Feb 15 11:15:03.052 CAM(core.ecm): 0.1: is idle now
Feb 15 11:15:03.052 CAM(core.ecm): 0.1: stop
Feb 15 11:15:03.052 CAM(core.au): 0: stopping chain 0602
Feb 15 11:15:03.052 CSA: Got command(1): I idx: 0 pid: 0
Feb 15 11:15:03.096 CAM(core.ecm): 0.1: triggered SID 19461/-1 idx 1/1 mode 3/0 sync
Feb 15 11:15:03.096 CAM(core.ecm): 0.1: new caDescr: <empty>
Cable: 01540000
Feb 15 11:15:03.887 CAM(core.pids): 0: tune to same source/transponder
Feb 15 11:15:03.887 CAM: FFdecsawrapper completed  Tune cmd
Feb 15 11:15:03.887 CAM(core.pids): 0: update SID 19501 (zero=0 noshift=0)
Feb 15 11:15:03.887 CAM(core.pids): 0: pids typ5=0c81 typ5=0c8b typ5=0ce5
Feb 15 11:15:03.887 CAM(core.pids): Ca descriptors after simplify (pidCa=0)
Feb 15 11:15:03.887 CAM(core.pids): prgca: 09 04 18 01 E0 32 09 04 18 50 E0 33 09 04 06 02 E0 C9 09 04 06 04 E1 2D
Feb 15 11:15:03.887 CAM(core.pids): pidca 0c81: <empty>
Feb 15 11:15:03.888 CAM(core.pids): pidca 0c8b: <empty>
Feb 15 11:15:03.888 CAM(core.pids): pidca 0ce5: <empty>
Feb 15 11:15:03.888 CAM(core.pids): 0: SID=19501 zero=0 | sid=-/-/- zero=-/-/- idle=1/-1/1
Feb 15 11:15:03.888 CAM(core.pids): 0: found handler for SID 19501 (0.1 idle=1 idx=1)
Feb 15 11:15:03.888 CAM(core.ecm): 0.1: setting new SID 19501
Feb 15 11:15:03.888 CAM(core.pids): 0.1: pids on entry
Feb 15 11:15:03.888 CAM(core.pids): 0.1: pids after delete
Feb 15 11:15:03.888 CAM(core.pids): 0: descrambling pid 0c81 on index 1
Feb 15 11:15:03.888 CSA: Got command(1): P idx: 1 pid: 3201
Feb 15 11:15:03.888 CAM(core.pids): 0: descrambling pid 0c8b on index 1
Feb 15 11:15:03.888 CSA: Got command(1): P idx: 1 pid: 3211
Feb 15 11:15:03.888 CAM(core.pids): 0: descrambling pid 0ce5 on index 1
Feb 15 11:15:03.888 CSA: Got command(1): P idx: 1 pid: 3301
Feb 15 11:15:03.888 CAM(core.pids): 0.1: pids after add typ5=0c81 typ5=0c8b typ5=0ce5
Feb 15 11:15:03.888 CAM(core.ecm): 0.1: is no longer idle
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: triggered SID -1/19501 idx 1/1 mode -1/0 -
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: new caDescr: 09 04 18 01 E0 32 09 04 18 50 E0 33 09 04 06 02 E0 C9 09 04 06 04 E1 2D
Feb 15 11:15:03.941 CAM(core.ecm): from cache: system Cardclient (0602) id 0000 with ecm c9/80
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: CA descriptors for SID 19501 (len=24)
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: descriptor 18 01 e0 32
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: found 1801(0000) (Nagra2) id 0000 with ecm 32/80 (new)
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: descriptor 18 50 e0 33
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: found 1850(0000) (Nagra2) id 0000 with ecm 33/80 (new)
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: descriptor 06 02 e0 c9
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: found 0602(0000) (Irdeto2) id 0000 with ecm c9/80 (already present)
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: descriptor 06 04 e1 2d
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: found 0604(0000) (Irdeto2) id 0000 with ecm 12d/80 (new)
Feb 15 11:15:03.941 CAM(core.ecm): 0.1: try system Cardclient (0602) id 0000 with ecm c9 (cached) (pri=-15)
Feb 15 11:15:03.993 CAM(core.au): 0: chain caid 1801 -> Nagra2(-10) [0064-82/fe]
Feb 15 11:15:03.993 CAM(core.au): 0: chain caid 1850 -> Nagra2(-10) [0065-82/fe]
Feb 15 11:15:03.993 CAM(core.au): 0: chain caid 0602 -> Irdeto2(-8) Irdeto(-10) Cardclient(-15) [0066-82/ff]
Feb 15 11:15:03.993 CAM(core.au): 0: chain caid 0604 -> Irdeto2(-8) Irdeto(-10) [0067-82/ff]
Feb 15 11:15:03.993 CAM(core.au): 0: chain caid 0606 -> Irdeto2(-8) Irdeto(-10) [0068-82/ff]
Feb 15 11:15:03.993 CAM(core.au): 0: starting chain 0602
Feb 15 11:15:04.238 CAM(cardclient.core): cc-loop
Feb 15 11:15:04.238 CAM(cardclient.core): now trying client Newcamd (192.168.178.30:15050)
Feb 15 11:15:04.450 CAM(core.ecm): 0.1: correct key found
Feb 15 11:15:04.451 CSA: Creating csa for rb: 1
Feb 15 11:17:17.082 CAM(core.au): 0: stopping chain 0602
Feb 15 11:17:17.082 CAM(core.au): 0: chain caid 1801 -> Nagra2(-10) [0064-82/fe]
Feb 15 11:17:17.082 CAM(core.au): 0: chain caid 1850 -> Nagra2(-10) [0065-82/fe]
Feb 15 11:17:17.082 CAM(core.au): 0: chain caid 0602 -> Irdeto2(-8) Irdeto(-10) Cardclient(-15) [0266-82/ff]
Feb 15 11:17:17.082 CAM(core.au): 0: chain caid 0604 -> Irdeto2(-8) Irdeto(-10) [0067-82/ff]
Feb 15 11:17:17.082 CAM(core.au): 0: chain caid 0606 -> Irdeto2(-8) Irdeto(-10) [0068-82/ff]
Feb 15 11:17:17.082 CAM(core.au): 0: starting chain 0602
Feb 15 11:17:17.157 CAM(core.au): 0: stopping chain 0602
Feb 15 11:17:17.157 CAM(core.au): 0: chain caid 1801 -> Nagra2(-10) [0064-82/fe]
Feb 15 11:17:17.157 CAM(core.au): 0: chain caid 1850 -> Nagra2(-10) [0065-82/fe]
Feb 15 11:17:17.157 CAM(core.au): 0: chain caid 0602 -> Irdeto2(-8) Irdeto(-10) Cardclient(-15) [0066-82/ff]
Feb 15 11:17:17.157 CAM(core.au): 0: chain caid 0604 -> Irdeto2(-8) Irdeto(-10) [0067-82/ff]
Feb 15 11:17:17.157 CAM(core.au): 0: chain caid 0606 -> Irdeto2(-8) Irdeto(-10) [0068-82/ff]
Feb 15 11:17:17.157 CAM(core.au): 0: starting chain 0602
Feb 15 11:17:28.482 CAM(core.au): 0: stopping chain 0602
Feb 15 11:17:28.482 CAM(core.au): 0: chain caid 1801 -> Nagra2(-10) [0064-82/fe]
Feb 15 11:17:28.482 CAM(core.au): 0: chain caid 1850 -> Nagra2(-10) [0065-82/fe]
Feb 15 11:17:28.557 CAM(core.au): 0: chain caid 1801 -> Nagra2(-10) [0064-82/fe]
Feb 15 11:17:28.557 CAM(core.au): 0: chain caid 1850 -> Nagra2(-10) [0065-82/fe]
Feb 15 11:17:28.557 CAM(core.au): 0: chain caid 0602 -> Irdeto2(-8) Irdeto(-10) Cardclient(-15) [0066-82/ff]
Feb 15 11:17:28.557 CAM(core.au): 0: chain caid 0604 -> Irdeto2(-8) Irdeto(-10) [0067-82/ff]
Feb 15 11:17:28.557 CAM(core.au): 0: chain caid 0606 -> Irdeto2(-8) Irdeto(-10) [0068-82/ff]
Feb 15 11:17:28.557 CAM(core.au): 0: starting chain 0602

dmesg shows the following additional kernel messages:

[66593.040492] ffdecsawrapper[3560]: segfault at 7f5e792295cc ip 000000000048c580 sp 00007f5d79229270 error 4 in ffdecsawrapper[400000+da000]
[66594.089454] dvblb_fake_ioctl interrupted: 6
[66769.715044] dvblb_fake_ioctl interrupted: 2150133582
[66770.714533] dvblb_fake_ioctl interrupted: 1076129612

[bas-t]

Please try this: create a new file in /etc/camfiles called 'override.conf'

depending on your region (your smartcard entitles you to either 0604 or 0602) it should read a single line:

ignore:{*}0602:0606:1801:1850

this is in case your smartcard has 0604

ignore:{*}0604:0606:1801:1850

in case your smartcard has 0602

I hope this solves your issue, I still can't reproduce the segfaults.

[epienbroek]

I've just added the override and restarted ffdecsawrapper. Fingers crossed now :)

[bas-t]

BTW, your patch for dvb_loopback.c is good, I pushed it. But your patch for v4l-make-install.patch is replaced by https://github.com/bas-t/dvbloopback/commit/ec96f1a4ffe006201be5e3e7b6c7495d0aad738f

[epienbroek]

ffdecsawrapper seems to run more stable now (no segfaults in the last 20 hours), but now I'm running into a different issue: Now that ffdecsawrapper is running for about 20 hours, MythTV is not able to tune in to encrypted channels any more. All free-to-air channels work fine (both SD and HD), but while tuning to encrypted ones MythTV will remain stuck in the 'partial lock' status.

This happened before to me as well and a restart of both ffdecsawrapper and MythTV was enough to get it working again, but that obviously isn't a proper solution.

It looks like ffdecsawrapper did have a connection with oscam initially. Here's the oscam log (the timezone in this log file is 1 hour off, local time was 21:43:08):

2016/02/17 20:43:08 7754B96F c   (client) encrypted newcamd:15050-client 192.168.178.21 granted (oscamuser1, au=on (1 reader))
2016/02/17 20:43:08 7754B96F c  (newcamd) user oscamuser1 authenticated successfully (generic)
2016/02/17 20:43:08 7754B96F c  (newcamd) AU enabled for user oscamuser1 on reader ziggo
2016/02/17 20:45:09 7754B96F c   (client) oscamuser1 disconnected from 192.168.178.21

After this there has been no more logfile activity in oscam

Here's the ffdecsawrapper log:

Feb 17 21:43:08.426 INIT: Loading v1.0.3-4-gf7114a1-Master
Feb 17 21:43:08.426 CAM: initializing FFdecsawrapper, A software emulated CAM
Feb 17 21:43:08.426 CAM(core.load): ** Key updates (AU) are enabled (active CAIDs) (no prestart)
Feb 17 21:43:08.426 CAM(core.load): ** Local systems DON'T take priority over cached remote
Feb 17 21:43:08.426 CAM(core.load): ** Force transfermode with digital audio
Feb 17 21:43:08.426 CAM(core.load): ** ECM cache is set to enabled
Feb 17 21:43:08.426 CAM(core.load): ** TsBufferSize is 32 MB
Feb 17 21:43:08.426 CAM(core.load): ** ScCaps are 1 2 0 0 0 0 0 0 0 0
Feb 17 21:43:08.426 CAM(general.info): loading overrides from /etc/camfiles/override.conf
Feb 17 21:43:08.426 CAM(core.override): ignore: * - caids 602 606 1801 1850
Feb 17 21:43:08.426 CAM(core.load): loaded 1 overrides from /etc/camfiles/override.conf
Feb 17 21:43:08.427 CAM(general.info): loading smartcard data from /etc/camfiles/smartcard.conf
Feb 17 21:43:08.427 CAM(core.load): loaded 0 smartcard data from /etc/camfiles/smartcard.conf
Feb 17 21:43:08.427 CAM(general.error): failed open /etc/camfiles/cardslot.conf: No such file or directory
Feb 17 21:43:08.427 CAM(general.info): loading ecm cache from /etc/camfiles/ecm.cache
Feb 17 21:43:08.429 CAM(general.error): failed open /etc/camfiles/SoftCam.Key: No such file or directory
Feb 17 21:43:08.429 CAM(general.info): loading cardclient config from /etc/camfiles/cardclient.conf
Feb 17 21:43:08.429 CAM(cardclient.newcamd): now using protocol version 525 (cdLen=8)
Feb 17 21:43:08.429 CAM(cardclient.core): hostname=192.168.178.30 port=15050 emm=1 emmCaids 0602/fff0
Feb 17 21:43:08.429 CAM(cardclient.core): client 'Newcamd' ready
Feb 17 21:43:08.430 CAM(core.net): connecting to 192.168.178.30:15050/tcp (192.168.178.30)
Feb 17 21:43:08.431 THREAD: Netwatcher thread started (pid=29250, tid=140376873735936)
Feb 17 21:43:08.459 CAM(cardclient.login): Newcamd: CaID=0602 admin=1 srvUA=0000000019A6C89B provider 000004/0000000000000000 000003/0000000002FFFFFF 000002/0000000002FFFFFF 000001/0000000001000600 000000/0000000000059450
Feb 17 21:43:08.459 CAM(general.info): no keys loaded for softcam
Feb 17 21:43:08.459 CAM(core.load): ** registered systems:
Feb 17 21:43:08.459 CAM(core.load): ** Viaccess          (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** Seca              (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** SC-VideoGuard2    (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Viaccess       (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Seca           (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Nagra          (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Irdeto         (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Cryptoworks    (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** SC-Conax          (pri  -5)
Feb 17 21:43:08.459 CAM(core.load): ** Fake-NDS          (pri -12)
Feb 17 21:43:08.459 CAM(core.load): ** Nagra2            (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** Nagra             (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** Irdeto2           (pri  -8)
Feb 17 21:43:08.459 CAM(core.load): ** Irdeto            (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** Cryptoworks       (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** ConstCW           (pri -20)
Feb 17 21:43:08.459 CAM(core.load): ** Conax             (pri -10)
Feb 17 21:43:08.459 CAM(core.load): ** Cardclient        (pri -15)
Feb 17 21:43:08.459 THREAD: SC housekeeper thread started (pid=29250, tid=140376862721792)
Feb 17 21:43:09.467 demux: Starting thread on /dev/dvb/adapter1/demux1
The thread scheduling parameters indicate:
policy = 0
priority = 0
Feb 17 21:43:09.467 dvr: Starting thread on /dev/dvb/adapter1/dvr1
The thread scheduling parameters indicate:
policy = 1
priority = 99
Feb 17 21:43:09.467 frontend: Starting thread on /dev/dvb/adapter1/frontend1
The thread scheduling parameters indicate:
policy = 0
priority = 0
Feb 17 21:43:09.467 : Listening on port 5456
Feb 17 21:43:42.040 CSA: Got command(1): I idx: 0 pid: 0
Feb 17 21:43:42.049 CSA: Got command(1): I idx: 0 pid: 0
Feb 17 21:43:42.068 CHANNEL: Tuning frontend
Feb 17 21:43:42.068 CSA: Got command(1): I idx: 0 pid: 0
Feb 17 21:45:07.138 CHANNEL: Tuning frontend
Feb 17 21:45:07.138 CSA: Got command(1): I idx: 0 pid: 0
Feb 17 21:45:07.364 CSA: Removing csa for rb: 1
Cable: 01540000
Feb 17 21:45:09.326 CHANNEL: read_pmt expected table 0x02 but got 0x00
Feb 17 21:45:09.440 CAM(core.net): idle timeout, disconnected 192.168.178.30:15050
Feb 17 21:45:10.551 CHANNEL: skip: 256 > count: 40 - 12 || count > size: 44
Feb 17 21:45:10.753 CHANNEL: read_pmt expected table 0x02 but got 0x00
Feb 17 21:45:11.026 CHANNEL: skip: 143 > count: 40 - 12 || count > size: 44
Feb 17 21:45:14.247 CSA: Removing csa for rb: 1

<<snip>>

Feb 18 17:17:22.492 CSA: Removing csa for rb: 1
Feb 18 17:17:22.494 CHANNEL: Tuning frontend
Feb 18 17:17:22.494 CSA: Got command(1): I idx: 0 pid: 0
Feb 18 17:17:29.640 CSA: Removing csa for rb: 1
Feb 18 17:19:23.970 CHANNEL: read_nit expected table 0x40  or 0x41 but got 0x46
Feb 18 17:19:47.707 CHANNEL: Tuning frontend
Feb 18 17:19:47.707 CSA: Got command(1): I idx: 0 pid: 0
Feb 18 17:24:33.831 CSA: Removing csa for rb: 1
Feb 18 17:24:33.834 CHANNEL: Tuning frontend
Feb 18 17:24:33.834 CSA: Got command(1): I idx: 0 pid: 0
Feb 18 17:25:38.360 CSA: Removing csa for rb: 1
Feb 18 17:25:38.363 CHANNEL: Tuning frontend
Feb 18 17:25:38.363 CSA: Got command(1): I idx: 0 pid: 0

And finally the mythbackend log:

feb 18 17:19:47 foobar mythbackend[29279]: 2016-02-18 17:19:47.922059 N  DTVSigMon[1](/dev/dvb/adapter1/frontend0): PMT says program 19281 is encrypted
feb 18 17:19:49 foobar mythbackend[29279]: 2016-02-18 17:19:49.828789 I  MPEGStream[1](0x7feaf42e40f8): PID 0x7dc status: Encrypted
feb 18 17:19:51 foobar mythbackend[29279]: 2016-02-18 17:19:51.712285 I  MPEGStream[1](0x7feaf42e40f8): PID 0x7db status: Encrypted
feb 18 17:22:01 foobar mythbackend[29279]: 2016-02-18 17:22:01.377358 N  AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
feb 18 17:24:30 foobar mythbackend[29279]: 2016-02-18 17:24:30.543780 I  MainServer::ANN Monitor
feb 18 17:24:30 foobar mythbackend[29279]: 2016-02-18 17:24:30.543789 I  adding: foobar as a client (events: 0)
feb 18 17:24:30 foobar mythbackend[29279]: 2016-02-18 17:24:30.551238 I  MainServer::ANN Monitor
feb 18 17:24:30 foobar mythbackend[29279]: 2016-02-18 17:24:30.551245 I  adding: foobar as a client (events: 1)
feb 18 17:24:30 foobar mythbackend[29279]: 2016-02-18 17:24:30.552719 I  New DB connection, total: 9
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.616983 I  MainServer::ANN Playback
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.616993 I  adding: foobar as a client (events: 0)
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.626047 E   MainServer::HandleRecorderQuery() Command GET_FREE_INPUTS for unconnected encoder 3
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.626336 E   MainServer::HandleRecorderQuery() Command GET_FREE_INPUTS for unconnected encoder 4
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.720004 I  TVRec[1]: Changing from None to WatchingLiveTV
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.734871 I  TVRec[1]: HW Tuner: 1->1
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.877888 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.889345 W  DVBSigMon[1](/dev/dvb/adapter1/frontend0): Cannot measure Signal Strength
feb 18 17:24:33 foobar mythbackend[29279]: eno: Operation not supported (95)
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.889371 W  DVBSigMon[1](/dev/dvb/adapter1/frontend0): Cannot measure S/N
feb 18 17:24:33 foobar mythbackend[29279]: eno: Operation not supported (95)
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.889392 W  DVBSigMon[1](/dev/dvb/adapter1/frontend0): Cannot measure Bit Error Rate
feb 18 17:24:33 foobar mythbackend[29279]: eno: Operation not supported (95)
feb 18 17:24:33 foobar mythbackend[29279]: 2016-02-18 17:24:33.889412 W  DVBSigMon[1](/dev/dvb/adapter1/frontend0): Cannot count Uncorrected Blocks
feb 18 17:24:33 foobar mythbackend[29279]: eno: Operation not supported (95)
feb 18 17:24:34 foobar mythbackend[29279]: 2016-02-18 17:24:34.037172 N  DTVSigMon[1](/dev/dvb/adapter1/frontend0): PMT says program 19461 is encrypted
feb 18 17:24:35 foobar mythbackend[29279]: 2016-02-18 17:24:35.941847 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7dc status: Encrypted
feb 18 17:24:36 foobar mythbackend[29279]: 2016-02-18 17:24:36.098366 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted
feb 18 17:24:36 foobar mythbackend[29279]: 2016-02-18 17:24:36.807591 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Unknown
feb 18 17:24:36 foobar mythbackend[29279]: 2016-02-18 17:24:36.891990 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7db status: Encrypted
feb 18 17:24:39 foobar mythbackend[29279]: 2016-02-18 17:24:39.056340 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted
feb 18 17:24:40 foobar mythbackend[29279]: 2016-02-18 17:24:40.170660 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Unknown
feb 18 17:24:45 foobar mythbackend[29279]: 2016-02-18 17:24:45.296126 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted
feb 18 17:24:46 foobar mythbackend[29279]: 2016-02-18 17:24:46.898107 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Unknown
feb 18 17:24:50 foobar mythbackend[29279]: 2016-02-18 17:24:50.902718 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted
feb 18 17:24:51 foobar mythbackend[29279]: 2016-02-18 17:24:51.445827 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Unknown
feb 18 17:24:52 foobar mythbackend[29279]: 2016-02-18 17:24:52.815194 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted
feb 18 17:24:53 foobar mythbackend[29279]: 2016-02-18 17:24:53.527686 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Unknown
feb 18 17:24:58 foobar mythbackend[29279]: 2016-02-18 17:24:58.116477 I  MPEGStream[1](0x7feaf42e77e8): PID 0x7d1 status: Encrypted

The time 17:24:33 was the moment I tried to open live TV on a mythtv frontend (which resulted in mythtv getting stuck at the 'waiting for partial lock')

In the ffdecsawrapper logs the following draws my attention:

Feb 17 21:43:08.430 CAM(core.net): connecting to 192.168.178.30:15050/tcp (192.168.178.30)
Feb 17 21:45:09.440 CAM(core.net): idle timeout, disconnected 192.168.178.30:15050

Is this expected behavior of ffdecsawrapper or perhaps a misconfiguration on my end?

[bas-t]

Hmm, obviously mythtv does something wrong while tuning. Even I can't imagine that the Ziggo guys screwed up that bad. This should never happen: Feb 17 21:45:09.326 CHANNEL: read_pmt expected table 0x02 but got 0x00

This is even worse: Feb 18 17:19:23.970 CHANNEL: read_nit expected table 0x40 or 0x41 but got 0x46

Did you set the network id to 5555 in mythtv-setup?

About your last remark: yes, that's expected behavior.

[bas-t]

BTW: you're not running the latest ffdecsawrapper binary. Your log should start with: INIT: Loading v2.0.0-5-g8d30629-Master

[epienbroek]

Those read_pmt and read_nit messages happening are more often. Here are the unique ones:

CHANNEL: read_pmt expected table 0x02 but got 0x00
CHANNEL: read_pmt expected table 0x02 but got 0x01
CHANNEL: read_pmt expected table 0x02 but got 0x03
CHANNEL: read_pmt expected table 0x02 but got 0x06
CHANNEL: read_pmt expected table 0x02 but got 0x0a
CHANNEL: read_pmt expected table 0x02 but got 0x0e
CHANNEL: read_pmt expected table 0x02 but got 0x12
CHANNEL: read_pmt expected table 0x02 but got 0x13
CHANNEL: read_pmt expected table 0x02 but got 0x40
CHANNEL: read_pmt expected table 0x02 but got 0x41
CHANNEL: read_pmt expected table 0x02 but got 0x42
CHANNEL: read_pmt expected table 0x02 but got 0x4f
CHANNEL: read_pmt expected table 0x02 but got 0x60
CHANNEL: read_pmt expected table 0x02 but got 0x83
CHANNEL: read_pmt expected table 0x02 but got 0xb1
CHANNEL: read_pmt expected table 0x02 but got 0xd7
CHANNEL: read_pmt expected table 0x02 but got 0xe0

read_nit expected table 0x40  or 0x41 but got 0x00
read_nit expected table 0x40  or 0x41 but got 0x02
read_nit expected table 0x40  or 0x41 but got 0x46
read_nit expected table 0x40  or 0x41 but got 0x4e
read_nit expected table 0x40  or 0x41 but got 0x4f
read_nit expected table 0x40  or 0x41 but got 0x51
read_nit expected table 0x40  or 0x41 but got 0x60
read_nit expected table 0x40  or 0x41 but got 0x69
read_nit expected table 0x40  or 0x41 but got 0x80
read_nit expected table 0x40  or 0x41 but got 0xe0
read_nit expected table 0x40  or 0x41 but got 0xf0

It could be a weak signal on my end which is causing these errors (unless checksum verifications are already done before these pmt and nit messages are processed. I'm not familiar enough with the DVB-C standard to know where checksums are used).

In MythTV I do have the network-id set to 5555 in the Video Source Setup. I also tried to verify this in the MythTV database, but for some reason it thinks that the various DVB multiplexes are on network id 1536 (unless I'm using the wrong query):

MariaDB [mythconverg]> select mplexid, transportid, networkid, frequency, symbolrate, modulation from dtv_multiplex order by mplexid;
+---------+-------------+-----------+-----------+------------+------------+
| mplexid | transportid | networkid | frequency | symbolrate | modulation |
+---------+-------------+-----------+-----------+------------+------------+
|     955 |          18 |      1536 | 474000000 |    6875000 | qam_64     |
|     956 |        2049 |      1536 | 826000000 |    6900000 | qam_256    |
|     957 |        2050 |      1536 | 562000000 |    6900000 | qam_256    |
|     958 |        2051 |      1536 | 786000000 |    6900000 | qam_256    |
|     959 |        2052 |      1536 | 810000000 |    6900000 | qam_256    |
|     960 |        2053 |      1536 | 802000000 |    6900000 | qam_256    |
|     961 |        2054 |      1536 | 490000000 |    6900000 | qam_256    |
|     962 |        2055 |      1536 | 346000000 |    6900000 | qam_256    |
|     964 |        2057 |      1536 | 330000000 |    6900000 | qam_256    |
|     967 |        2060 |      1536 | 818000000 |    6900000 | qam_256    |
|     968 |        2061 |      1536 | 354000000 |    6900000 | qam_256    |
|     969 |        2062 |      1536 | 370000000 |    6900000 | qam_256    |
|     970 |        2063 |      1536 | 378000000 |    6900000 | qam_256    |
|     972 |        2066 |      1536 | 794000000 |    6900000 | qam_256    |
|     973 |        2068 |      1536 | 162000000 |    6900000 | qam_256    |
|     975 |        2070 |      1536 | 314000000 |    6900000 | qam_256    |
|     976 |        2071 |      1536 | 554000000 |    6900000 | qam_256    |
|     977 |        2074 |      1536 | 466000000 |    6900000 | qam_256    |
|     980 |        2099 |      1536 | 394000000 |    6900000 | qam_256    |
|     981 |        2100 |      1536 | 450000000 |    6900000 | qam_256    |
|     982 |        2101 |      1536 | 458000000 |    6900000 | qam_256    |
|     984 |        2103 |      1536 | 698000000 |    6900000 | qam_256    |
|     985 |        2106 |      1536 | 586000000 |    6900000 | qam_256    |
|     986 |        2107 |      1536 | 770000000 |    6900000 | qam_256    |
|     987 |        2112 |      1536 | 362000000 |    6900000 | qam_256    |
|     989 |        3003 |      1536 | 122000000 |    6900000 | qam_256    |
|     991 |        2067 |      1536 | 722000000 |    6900000 | qam_256    |
|     992 |        2073 |      1536 | 546000000 |    6900000 | qam_256    |
|     993 |        2076 |      1536 | 578000000 |    6900000 | qam_256    |
|     994 |        3004 |      1536 | 834000000 |    6900000 | qam_256    |
|     995 |        2058 |      1536 | 338000000 |    6900000 | qam_256    |
|     996 |        2059 |      1536 | 306000000 |    6900000 | qam_256    |
|     997 |        2064 |      1536 | 522000000 |    6900000 | qam_256    |
|     998 |        2069 |      1536 | 778000000 |    6900000 | qam_256    |
|     999 |        2097 |      1536 | 842000000 |    6900000 | qam_256    |
|    1000 |        2102 |      1536 | 498000000 |    6900000 | qam_256    |
|    1001 |        2056 |      1536 | 322000000 |    6900000 | qam_256    |
|    1002 |        2098 |      1536 | 386000000 |    6900000 | qam_256    |
|    1004 |        3002 |      1536 | 170000000 |    6900000 | qam_256    |
|    1005 |        3002 |         0 | 170000000 |    6900000 | qam_256    |
+---------+-------------+-----------+-----------+------------+------------+
40 rows in set (0.00 sec)

The last time I did a full channel scan (deleting all old channel entries first) was about 4 weeks ago and I'm certain that the network id used in the Video Source Setup was already set to 5555 back then. I don't remember any more if I also deleted all known multiplexes before starting the full channel scan. On https://ziggo-gebruikers.nl/forum/showthread.php?t=48684&page=3 I've found that network-id 1536 seems to be the ONID (original network id) of the UPC network. I could try to remove all old multiplexes from MythTV and performing another full channel scan to see if that helps in using the correct network-id.

The ffdecsawrapper binary which I'm using is forked from commit de36a09ab86c7a6e0c1c46039c5370ad93921355 (master branch, nov 17 2015). The only commits which were applied after that are b3a3f9a0d84f7269da8dacee4ba55ba73138a254, be1ecb3474bc2f360e597b630f85ff40b230c046 and 51bc5406823e3ad2caa8a6b80991c32e79ec0559 but those shouldn't be related to my issue

[bas-t]

If youŕe going to do a full scan, please truncate the following: TRUNCATE TABLE mythconverg.channel; TRUNCATE TABLE mythconverg.channelscan; TRUNCATE TABLE mythconverg.channelscan_channel; TRUNCATE TABLE mythconverg.channelscan_dtv_multiplex; TRUNCATE TABLE mythconverg.dtv_multiplex; TRUNCATE TABLE mythconverg.eit_cache; TRUNCATE TABLE mythconverg.program;

The onid should stay as it is. My knowledge of dvb standards is not exactly good either, I'm just a somewhat advanced hobbyist.

The other day I saw a comment from Jaroslav Kysela (he really knows dvb stuff, he's the main dev of tvheadend) regarding similar pmt and nit errors. He said that the driver is sending garbage to the decrypting system.

[bas-t]

Interesting thread: http://forum.odroid.com/viewtopic.php?f=117&t=10847#p84771 It states that your tuner won't work without the media controller for dvb set to enabled. Now I guess I've got something to chew on... Don't hold your breath though, it may take some time...

[epienbroek]

I just tried to stop mythbackend, purge the tables you mentioned and start mythtv-setup (thus ffdecsawrapper was left running). Unfortunately mythtv-setup froze when I tried to get to the channel configuration. Here's a snippet from a gdb backtrace of mythtv-setup:

Thread 1 (Thread 0x7fd621a19900 (LWP 35779)):
#0  0x00007fd617b349cd in open64 () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007fd61f596932 in CardUtil::ProbeDVBType(QString const&) () from /lib64/libmythtv-0.27.so.0
#2  0x00007fd61f596fbb in CardUtil::ProbeSubTypeName(unsigned int) () from /lib64/libmythtv-0.27.so.0
#3  0x00007fd61f9dd8e1 in ScanTypeSetting::SetInput(QString const&) () from /lib64/libmythtv-0.27.so.0
#4  0x00007fd6160974aa in QMetaObject::activate(QObject*, QMetaObject const*, int, void**) () from /lib64/libQtCore.so.4

After a while I tried to restart ffdecsawrapper (with mythtv-setup still 'frozen'). As I'm using systemd to stop/start ffdecsawrapper the following messages started to appear in the system log:

feb 19 19:08:32 foobar kernel: dvblb_fake_ioctl interrupted: 4
feb 19 19:09:04 foobar systemd[1]: Stopping FFdecsawrapper - FFdecsa Empowered Softcam...
feb 19 19:09:34 foobar systemd[1]: ffdecsawrapper.service stop-sigterm timed out. Killing.
feb 19 19:09:48 foobar kernel: dvblb_fake_ioctl interrupted: 4
feb 19 19:10:04 foobar systemd[1]: ffdecsawrapper.service still around after SIGKILL. Ignoring.
feb 19 19:10:35 foobar systemd[1]: ffdecsawrapper.service stop-final-sigterm timed out. Killing.

Even with this final kill, ffdecsawrapper refuses to die and now remains a zombie process:

# ps ax | grep ffdec
29250 ?        Zsl  179:36 [ffdecsawrapper] <defunct>

The fun isn't over yet, now the kernel complains that two tasks are hung, one being ffdecsawrapper, the other one being the DVB driver:

feb 19 19:11:02 foobar kernel: INFO: task ffdecsawrapper:29254 blocked for more than 120 seconds.
feb 19 19:11:02 foobar kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
feb 19 19:11:02 foobar kernel: ffdecsawrapper  D ffff88003695fc00     0 29254      1 0x00000084
feb 19 19:11:02 foobar kernel:  ffff88002265fa70 0000000000000086 ffff88003688d080 ffff88002265ffd8
feb 19 19:11:02 foobar kernel:  ffff88002265ffd8 ffff88002265ffd8 ffff88003688d080 ffff8800752dbf08
feb 19 19:11:02 foobar kernel:  ffff8800752dbf10 7fffffffffffffff ffff88003688d080 ffff88003695fc00
feb 19 19:11:02 foobar kernel: Call Trace:
feb 19 19:11:02 foobar kernel:  [<ffffffff8164f519>] schedule+0x29/0x70
feb 19 19:11:02 foobar kernel:  [<ffffffff8164d209>] schedule_timeout+0x209/0x2d0
feb 19 19:11:02 foobar kernel:  [<ffffffff810bb685>] ? sched_clock_cpu+0x85/0xc0
feb 19 19:11:02 foobar kernel:  [<ffffffff810b5d85>] ? check_preempt_curr+0x75/0xa0
feb 19 19:11:02 foobar kernel:  [<ffffffff810b5dc9>] ? ttwu_do_wakeup+0x19/0xd0
feb 19 19:11:02 foobar kernel:  [<ffffffff8164f8e6>] wait_for_completion+0x116/0x170
feb 19 19:11:02 foobar kernel:  [<ffffffff810b8c10>] ? wake_up_state+0x20/0x20
feb 19 19:11:02 foobar kernel:  [<ffffffff810a5d5a>] kthread_stop+0x4a/0xe0
feb 19 19:11:02 foobar kernel:  [<ffffffffa05aca3e>] dvb_frontend_stop+0x4e/0xe0 [dvb_core]
feb 19 19:11:02 foobar kernel:  [<ffffffffa05acd78>] dvb_frontend_open+0x2a8/0x400 [dvb_core]
feb 19 19:11:02 foobar kernel:  [<ffffffffa05a35b8>] dvb_device_open+0x88/0xd0 [dvb_core]
feb 19 19:11:02 foobar kernel:  [<ffffffff811e31c1>] chrdev_open+0xa1/0x1e0
feb 19 19:11:02 foobar kernel:  [<ffffffff811dc0e7>] do_dentry_open+0x1a7/0x2e0
feb 19 19:11:02 foobar kernel:  [<ffffffff811e3120>] ? cdev_put+0x30/0x30
feb 19 19:11:02 foobar kernel:  [<ffffffff811dc319>] vfs_open+0x39/0x70
feb 19 19:11:02 foobar kernel:  [<ffffffff811eb91d>] do_last+0x1ed/0x12a0
feb 19 19:11:02 foobar kernel:  [<ffffffff811ee6b2>] path_openat+0xc2/0x490
feb 19 19:11:02 foobar kernel:  [<ffffffff811efeeb>] do_filp_open+0x4b/0xb0
feb 19 19:11:02 foobar kernel:  [<ffffffff811fcb07>] ? __alloc_fd+0xa7/0x130
feb 19 19:11:02 foobar kernel:  [<ffffffff811dd7f3>] do_sys_open+0xf3/0x1f0
feb 19 19:11:02 foobar kernel:  [<ffffffff811dd90e>] SyS_open+0x1e/0x20
feb 19 19:11:02 foobar kernel:  [<ffffffff8165a549>] system_call_fastpath+0x16/0x1b
feb 19 19:11:02 foobar kernel: INFO: task kdvb-ad-0-fe-0:29288 blocked for more than 120 seconds.
feb 19 19:11:02 foobar kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
feb 19 19:11:02 foobar kernel: kdvb-ad-0-fe-0  D ffff8800752dbd80     0 29288      2 0x00000080
feb 19 19:11:02 foobar kernel:  ffff8800752dbd10 0000000000000046 ffff8800a3978000 ffff8800752dbfd8
feb 19 19:11:02 foobar kernel:  ffff8800752dbfd8 ffff8800752dbfd8 ffff8800a3978000 ffff8800752dbd90
feb 19 19:11:02 foobar kernel:  ffff880147f9c098 0000000000000002 ffffffffa057f2e0 ffff8800752dbd80
feb 19 19:11:02 foobar kernel: Call Trace:
feb 19 19:11:02 foobar kernel:  [<ffffffffa057f2e0>] ? dvb_usb_data_complete_204+0x20/0x20 [dvb_usb_v2]
feb 19 19:11:02 foobar kernel:  [<ffffffff8164f519>] schedule+0x29/0x70
feb 19 19:11:02 foobar kernel:  [<ffffffffa057f2ee>] wait_schedule+0xe/0x20 [dvb_usb_v2]
feb 19 19:11:02 foobar kernel:  [<ffffffff8164d390>] __wait_on_bit+0x60/0x90
feb 19 19:11:02 foobar kernel:  [<ffffffffa057f2e0>] ? dvb_usb_data_complete_204+0x20/0x20 [dvb_usb_v2]
feb 19 19:11:02 foobar kernel:  [<ffffffff8164d447>] out_of_line_wait_on_bit+0x87/0xb0
feb 19 19:11:02 foobar kernel:  [<ffffffff810a6b60>] ? wake_atomic_t_function+0x40/0x40
feb 19 19:11:02 foobar kernel:  [<ffffffffa057fec4>] dvb_usb_fe_sleep+0xf4/0x190 [dvb_usb_v2]
feb 19 19:11:02 foobar kernel:  [<ffffffffa05af18f>] dvb_frontend_thread+0x53f/0xa40 [dvb_core]
feb 19 19:11:02 foobar kernel:  [<ffffffff810a6ae0>] ? wake_up_atomic_t+0x30/0x30
feb 19 19:11:02 foobar kernel:  [<ffffffffa05aec50>] ? dvb_frontend_ioctl_legacy.isra.10+0xd00/0xd00 [dvb_core]
feb 19 19:11:02 foobar kernel:  [<ffffffff810a5aef>] kthread+0xcf/0xe0
feb 19 19:11:02 foobar kernel:  [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
feb 19 19:11:02 foobar kernel:  [<ffffffff8165a498>] ret_from_fork+0x58/0x90
feb 19 19:11:02 foobar kernel:  [<ffffffff810a5a20>] ? kthread_create_on_node+0x140/0x140
feb 19 19:11:05 foobar systemd[1]: ffdecsawrapper.service still around after final SIGKILL. Entering failed mode.
feb 19 19:11:05 foobar systemd[1]: Unit ffdecsawrapper.service entered failed state.
feb 19 19:11:05 foobar systemd[1]: ffdecsawrapper.service failed.

Does this sound like the media controller mayhem you were worried about?

[bas-t]

Absolutely not. Since mythtv refuses to die, it still has not freed the loopback adapters. So when you try to kill ffdecsawrapper, it can't free them too, but still asks the kernel to unload the dvbloopback module. That is not possible to do, it's in use. So: reboot and try again. BTW, are you using centos mythtv packages? At the time I was playing with centos, they where great! (in sucking, but that goes for all other distro provided mythtv packages I ever tried...)

Op 19-02-16 om 19:32 schreef Erik van Pienbroek:

I just tried to stop mythbackend, purge the tables you mentioned and start mythtv-setup (thus ffdecsawrapper was left running). Unfortunately mythtv-setup froze when I tried to get to the channel configuration. Here's a snippet from a gdb backtrace of mythtv-setup:

|Thread 1 (Thread 0x7fd621a19900 (LWP 35779)): #0 0x00007fd617b349cd in open64 () at ../sysdeps/unix/syscall-template.S:81 #1 0x00007fd61f596932 in CardUtil::ProbeDVBType(QString const&) () from /lib64/libmythtv-0.27.so.0 #2 0x00007fd61f596fbb in CardUtil::ProbeSubTypeName(unsigned int) () from /lib64/libmythtv-0.27.so.0 #3 0x00007fd61f9dd8e1 in ScanTypeSetting::SetInput(QString const&) () from /lib64/libmythtv-0.27.so.0 #4 0x00007fd6160974aa in QMetaObject::activate(QObject, QMetaObject const, int, void**) () from /lib64/libQtCore.so.4 |

After a while I tried to restart ffdecsawrapper (with mythtv-setup still 'frozen'). As I'm using systemd to stop/start ffdecsawrapper the following messages started to appear in the system log:

|feb 19 19:08:32 foobar kernel: dvblb_fake_ioctl interrupted: 4 feb 19 19:09:04 foobar systemd[1]: Stopping FFdecsawrapper - FFdecsa Empowered Softcam... feb 19 19:09:34 foobar systemd[1]: ffdecsawrapper.service stop-sigterm timed out. Killing. feb 19 19:09:48 foobar kernel: dvblb_fake_ioctl interrupted: 4 feb 19 19:10:04 foobar systemd[1]: ffdecsawrapper.service still around after SIGKILL. Ignoring. feb 19 19:10:35 foobar systemd[1]: ffdecsawrapper.service stop-final-sigterm timed out. Killing. |

Even with this final kill, ffdecsawrapper refuses to die and now remains a zombie process:

|# ps ax | grep ffdec 29250 ? Zsl 179:36 [ffdecsawrapper] |

The fun isn't over yet, now the kernel complains that two tasks are hung, one being ffdecsawrapper, the other one being the DVB driver:

|feb 19 19:11:02 foobar kernel: INFO: task ffdecsawrapper:29254 blocked for more than 120 seconds. feb 19 19:11:02 foobar kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. feb 19 19:11:02 foobar kernel: ffdecsawrapper D ffff88003695fc00 0 29254 1 0x00000084 feb 19 19:11:02 foobar kernel: ffff88002265fa70 0000000000000086 ffff88003688d080 ffff88002265ffd8 feb 19 19:11:02 foobar kernel: ffff88002265ffd8 ffff88002265ffd8 ffff88003688d080 ffff8800752dbf08 feb 19 19:11:02 foobar kernel: ffff8800752dbf10 7fffffffffffffff ffff88003688d080 ffff88003695fc00 feb 19 19:11:02 foobar kernel: Call Trace: feb 19 19:11:02 foobar kernel: [] schedule+0x29/0x70 feb 19 19:11:02 foobar kernel: [] schedule_timeout+0x209/0x2d0 feb 19 19:11:02 foobar kernel: [] ? sched_clock_cpu+0x85/0xc0 feb 19 19:11:02 foobar kernel: [] ? check_preempt_curr+0x75/0xa0 feb 19 19:11:02 foobar kernel: [] ? ttwu_do_wakeup+0x19/0xd0 feb 19 19:11:02 foobar kernel: [] wait_for_completion+0x116/0x170 feb 19 19:11:02 foobar kernel: [] ? wake_up_state+0x20/0x20 feb 19 19:11:02 foobar kernel: [] kthread_stop+0x4a/0xe0 feb 19 19:11:02 foobar kernel: [] dvb_frontend_stop+0x4e/0xe0 [dvb_core] feb 19 19:11:02 foobar kernel: [] dvb_frontend_open+0x2a8/0x400 [dvb_core] feb 19 19:11:02 foobar kernel: [] dvb_device_open+0x88/0xd0 [dvb_core] feb 19 19:11:02 foobar kernel: [] chrdev_open+0xa1/0x1e0 feb 19 19:11:02 foobar kernel: [] do_dentry_open+0x1a7/0x2e0 feb 19 19:11:02 foobar kernel: [] ? cdev_put+0x30/0x30 feb 19 19:11:02 foobar kernel: [] vfs_open+0x39/0x70 feb 19 19:11:02 foobar kernel: [] do_last+0x1ed/0x12a0 feb 19 19:11:02 foobar kernel: [] path_openat+0xc2/0x490 feb 19 19:11:02 foobar kernel: [] do_filp_open+0x4b/0xb0 feb 19 19:11:02 foobar kernel: [] ? alloc_fd+0xa7/0x130 feb 19 19:11:02 foobar kernel: [] do_sys_open+0xf3/0x1f0 feb 19 19:11:02 foobar kernel: [] SyS_open+0x1e/0x20 feb 19 19:11:02 foobar kernel: [] system_call_fastpath+0x16/0x1b feb 19 19:11:02 foobar kernel: INFO: task kdvb-ad-0-fe-0:29288 blocked for more than 120 seconds. feb 19 19:11:02 foobar kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. feb 19 19:11:02 foobar kernel: kdvb-ad-0-fe-0 D ffff8800752dbd80 0 29288 2 0x00000080 feb 19 19:11:02 foobar kernel: ffff8800752dbd10 0000000000000046 ffff8800a3978000 ffff8800752dbfd8 feb 19 19:11:02 foobar kernel: ffff8800752dbfd8 ffff8800752dbfd8 ffff8800a3978000 ffff8800752dbd90 feb 19 19:11:02 foobar kernel: ffff880147f9c098 0000000000000002 ffffffffa057f2e0 ffff8800752dbd80 feb 19 19:11:02 foobar kernel: Call Trace: feb 19 19:11:02 foobar kernel: [] ? dvb_usb_data_complete_204+0x20/0x20 [dvb_usb_v2] feb 19 19:11:02 foobar kernel: [] schedule+0x29/0x70 feb 19 19:11:02 foobar kernel: [] wait_schedule+0xe/0x20 [dvb_usb_v2] feb 19 19:11:02 foobar kernel: [] wait_on_bit+0x60/0x90 feb 19 19:11:02 foobar kernel: [] ? dvb_usb_data_complete_204+0x20/0x20 [dvb_usb_v2] feb 19 19:11:02 foobar kernel: [] out_of_line_wait_on_bit+0x87/0xb0 feb 19 19:11:02 foobar kernel: [] ? wake_atomic_t_function+0x40/0x40 feb 19 19:11:02 foobar kernel: [] dvb_usb_fe_sleep+0xf4/0x190 [dvb_usb_v2] feb 19 19:11:02 foobar kernel: [] dvb_frontend_thread+0x53f/0xa40 [dvb_core] feb 19 19:11:02 foobar kernel: [] ? wake_up_atomic_t+0x30/0x30 feb 19 19:11:02 foobar kernel: [] ? dvb_frontend_ioctl_legacy.isra.10+0xd00/0xd00 [dvb_core] feb 19 19:11:02 foobar kernel: [] kthread+0xcf/0xe0 feb 19 19:11:02 foobar kernel: [] ? kthread_create_on_node+0x140/0x140 feb 19 19:11:02 foobar kernel: [] ret_from_fork+0x58/0x90 feb 19 19:11:02 foobar kernel: [] ? kthread_create_on_node+0x140/0x140 feb 19 19:11:05 foobar systemd[1]: ffdecsawrapper.service still around after final SIGKILL. Entering failed mode. feb 19 19:11:05 foobar systemd[1]: Unit ffdecsawrapper.service entered failed state. feb 19 19:11:05 foobar systemd[1]: ffdecsawrapper.service failed. |

Does this sound like the media controller mayhem you were worried about?

— Reply to this email directly or view it on GitHub https://github.com/bas-t/descrambler/issues/5#issuecomment-186352839.

[bas-t]

What's with this 'plus' kernel? Why don't you use the default stock kernel?

[epienbroek]

I've rebooted the machine now and am now trying to set up all channels again.

The MythTV package I'm using is from RPMFusion. Unfortunately RPMFusion doesn't have RHEL7/CentOS7 support yet so I took the Fedora version of the MythTV package and manually rebuilt it for the CentOS7 target. (If you're interested I can provide you the binary RPMs).

It's correct that I'm not using the stock kernel, but a 'plus' kernel. This is a CentOS-specific kernel where various kernel modules/features are enabled which aren't enabled in the stock kernel (in other words: modules/features which are not supported directly by Red Hat). The reason why I'm using the 'centosplus' kernel is because I2C MUX support is enabled in it

[bas-t]

Yeah, that I2C MUX support was a pain for me too. But I was not happy with the plus kernel either, so I figure I'd recompile the stock kernel. And while at it, put dvbloopback in it and backport my dvb-drivers to it, so I have it all complete in one go. The result resides in this repo:

https://github.com/bas-t/centos7-kernel

I've been looking at what this ODROID guy did, but I'm far from convinced. I remember having seen multiple regression reports about the driver you need. I think these regressions could be addressed by pulling your driver out of the dvbsky driver and put it back where it originated from: cxusb.c Wrote a patch, so you can try it if you like. I could only compile-test it.

You'll need a fresh clone of dvbloopback repo, it's in a new testing branch.

git clone -b media_controller https://github.com/bas-t/dvbloopback.git && cd dvbloopback

./configure --v4l=yes

This way your driver will be compiled with media_controller_dvb support (I very much doubt it needs it, but it should not hurt anymore like it did) and as said, using cxusb interface. Hope this helps.

Oh, you must delete all of your dvb adapters in mythtv and reconfigure them.

[epienbroek]

Some time ago I already noticed your centos7-kernel repo. I did try to use it back then, but it was too fragile to work with (iirc, the main repo had to be used as root user, but if you had placed the git checkout in /root then the build user would not be able to read its contents). Building complete kernels is also a bit too time-consuming in my opinion so I decided to stick with the old method using the dvbloopback configure script which only updates the V4L stack instead of the entire kernel.

BTW, I do have small improvement suggestion for the scripts in the centos7-kernel repo (that is: if you're still interested in maintaining it). Instead of using a dedicated build user and manually setting up all RPM macro stuff you can also use a tool called mock. This tool is able to build binary RPMs from a source RPM using a temporary chroot. By using mock the host environment won't get polluted with additional development packages/users/files. Once a build has completed you can retrieve the results from /var/lib/mock/$repo/result and remove the temporary environment with 'mock --clean'. See https://fedoraproject.org/wiki/Mock and https://fedoraproject.org/wiki/Using_Mock_to_test_package_builds for more details

Back to the DVB stability issues: While browsing through the media_tree git logs recently I also noticed that my DVB adapter used to be supported by the cxusb driver, but that it was moved over to the dvbsky driver a couple of months ago. I'm glad you already worked on preparing a patch to re-add support for my DVB adapter to the cxusb driver and I'm currently installing it on my environment. I'll keep you informed about the results.

[epienbroek]

Okay, I'm up and running with the cxusb driver. Unfortunately I'm running into a show-stopper: when trying to scan for channels MythTV indicates that there's no signal. To rule out dvbloopback I also tried to scan the original device (without ffdecsawrapper running) but that failed too. Finally to rule out MythTV itself I also tried dvbv5-scan, but that tool also reported no signal. I even tried removing the device from the machine for about 30 seconds and re-inserting it, but that also didn't help..

Here are the relevant dmesg pieces:

[    1.376281] usb 3-1.5: New USB device found, idVendor=0b48, idProduct=3014
[    1.376325] usb 3-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    1.376371] usb 3-1.5: Product: TechnoTrend USB-Stick
[    1.376403] usb 3-1.5: Manufacturer: CityCom GmbH
[    1.376434] usb 3-1.5: SerialNumber: 20131128
...
[   12.408644] media: module verification failed: signature and/or required key missing - tainting kernel
[   12.410034] media: Linux media interface: v0.10
[   12.447402] Linux video capture interface: v2.00
[   12.448393] WARNING: You are using an experimental version of the media stack.
    As the driver is backported to an older kernel, it doesn't offer
    enough quality for its usage in production.
    Use it with care.
Latest git patches (needed if you report a bug to linux-media@vger.kernel.org):
    ebf74137d4ea95cc98b557dc39b6411cc63edfcf Add drivers, patch dvb-core.
    f7b5dff0b59b20469b2a4889e6170c0069d37c8d [media] media: Use all bits of an enumeration
...
[   12.641587] WARNING: You are using an experimental version of the media stack.
    As the driver is backported to an older kernel, it doesn't offer
    enough quality for its usage in production.
    Use it with care.
Latest git patches (needed if you report a bug to linux-media@vger.kernel.org):
    ebf74137d4ea95cc98b557dc39b6411cc63edfcf Add drivers, patch dvb-core.
    f7b5dff0b59b20469b2a4889e6170c0069d37c8d [media] media: Use all bits of an enumeration
...
[   13.206701] WARNING: You are using an experimental version of the media stack.
    As the driver is backported to an older kernel, it doesn't offer
    enough quality for its usage in production.
    Use it with care.
Latest git patches (needed if you report a bug to linux-media@vger.kernel.org):
    ebf74137d4ea95cc98b557dc39b6411cc63edfcf Add drivers, patch dvb-core.
    f7b5dff0b59b20469b2a4889e6170c0069d37c8d [media] media: Use all bits of an enumeration
...
[   13.362610] dvb-usb: found a 'TechnoTrend TVStick CT2-4400' in warm state.
[   13.363843] dvb-usb: will pass the complete MPEG2 transport stream to the software demuxer.
[   13.365228] DVB: registering new adapter (TechnoTrend TVStick CT2-4400)
[   13.366407] usb 3-1.5: media controller created
[   13.368912] dvb-usb: MAC address: bc:ea:2b:44:03:0b
[   13.370387] dvb_create_media_entity: media entity 'dvb-demux' registered.
...
[   14.122083] i2c i2c-1: Added multiplexed i2c bus 2
[   14.123252] si2168 1-0064: Silicon Labs Si2168 successfully attached
[   14.134636] si2157 2-0060: Silicon Labs Si2147/2148/2157/2158 successfully attached
[   14.135856] usb 3-1.5: DVB: registering adapter 0 frontend 0 (Silicon Labs Si2168)...
[   14.137030] dvb_create_media_entity: media entity 'Silicon Labs Si2168' registered.
[   14.847027] Registered IR keymap rc-tt-1500
[   14.847104] input: IR-receiver inside an USB DVB receiver as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.5/rc/rc0/input2
[   14.847209] rc rc0: IR-receiver inside an USB DVB receiver as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.5/rc/rc0
[   14.847210] dvb-usb: schedule remote query interval to 150 msecs.
[   14.847213] dvb-usb: TechnoTrend TVStick CT2-4400 successfully initialized and connected.
[   14.847228] usbcore: registered new interface driver dvb_usb_cxusb
...
[   42.992158] dvbloopback: registering 1 adapters
[   42.992215] DVB: registering new adapter (DVB-LOOPBACK)
...
[   64.461022] si2168 1-0064: found a 'Silicon Labs Si2168-B40'
[   64.491726] si2168 1-0064: downloading firmware from file 'dvb-demod-si2168-b40-01.fw'
[   65.261183] si2168 1-0064: firmware version: 4.0.11
[   65.272466] si2157 2-0060: found a 'Silicon Labs Si2158-A20'
[   65.282360] si2157 2-0060: downloading firmware from file 'dvb-tuner-si2158-a20-01.fw'
[   66.343167] si2157 2-0060: firmware version: 2.1.6

Here's the logging from when I disconnected/reconnected the adapter:

[  936.157519] dvb-usb: bulk message failed: -71 (1/0)
[  936.157562] dvb-usb: error -71 while querying for an remote control event.
[  936.271862] usb 3-1.5: USB disconnect, device number 3
[  936.291313] dvb-usb: TechnoTrend TVStick CT2-4400 successfully deinitialized and disconnected.
[  961.514725] usb 3-1.6: new high-speed USB device number 4 using ehci-pci
[  961.600377] usb 3-1.6: New USB device found, idVendor=0b48, idProduct=3014
[  961.600428] usb 3-1.6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  961.600462] usb 3-1.6: Product: TechnoTrend USB-Stick
[  961.600486] usb 3-1.6: Manufacturer: CityCom GmbH
[  961.600508] usb 3-1.6: SerialNumber: 20131128
[  961.601477] dvb-usb: found a 'TechnoTrend TVStick CT2-4400' in warm state.
[  961.601552] dvb-usb: will pass the complete MPEG2 transport stream to the software demuxer.
[  961.601761] DVB: registering new adapter (TechnoTrend TVStick CT2-4400)
[  961.601798] usb 3-1.6: media controller created
[  961.603173] dvb-usb: MAC address: bc:ea:2b:44:03:0b
[  961.603481] dvb_create_media_entity: media entity 'dvb-demux' registered.
[  961.811162] i2c i2c-1: Added multiplexed i2c bus 2
[  961.811196] si2168 1-0064: Silicon Labs Si2168 successfully attached
[  961.814554] si2157 2-0060: Silicon Labs Si2147/2148/2157/2158 successfully attached
[  961.814618] usb 3-1.6: DVB: registering adapter 0 frontend 0 (Silicon Labs Si2168)...
[  961.814659] dvb_create_media_entity: media entity 'Silicon Labs Si2168' registered.
[  961.816022] Registered IR keymap rc-tt-1500
[  961.816117] input: IR-receiver inside an USB DVB receiver as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.6/rc/rc0/input3
[  961.816285] rc rc0: IR-receiver inside an USB DVB receiver as /devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.6/rc/rc0
[  961.816333] dvb-usb: schedule remote query interval to 150 msecs.
[  961.816362] dvb-usb: TechnoTrend TVStick CT2-4400 successfully initialized and connected.

As far as I can see the dmesg doesn't show anything suspicious. A potential area where it might go wrong is an incompatible firmware. I've seen that there are multiple firmware revisions floating around on the web..might as well give it a try..

[epienbroek]

Even with different firmware versions there's still no signal detected in combination with the cxusb driver.. Here are the various combinations I've tried:

dvb-demod-si2168-b40-01.fw version 4.0.11    dvb-tuner-si2158-a20-01.fw version 2.1.6
dvb-demod-si2168-b40-01.fw version 4.0.4     dvb-tuner-si2158-a20-01.fw version 2.1.9
dvb-demod-si2168-b40-01.fw version 4.0.4     dvb-tuner-si2158-a20-01.fw version 2.1.6
dvb-demod-si2168-b40-01.fw version 4.0.19    dvb-tuner-si2158-a20-01.fw version 2.1.9

On https://github.com/OpenELEC/dvb-firmware/commit/fb88eed23c12745bc264f5169f68a7f282b0ee25 I noticed someone had similar issues, but as can be seen in the table above a downgrade of the firmware to 4.0.4/2.1.6 unfortunately didn't help here.

[bas-t]

I must have screwed up something, I guess. I think I can do a better job by pulling in the complete 3.18 media stack and adjust the patch to that stack. That way I'd avoid having to deal with the complicated changes to the media core after that point. I'll try to find some time to do this tomorrow.

[epienbroek]

Just did some more testing here. Long story short: I suspect that the override which was added to the ffdecsawrapper configuration caused all decrypt attempts from encrypted channels to fail.

I just tried again with the latest dvbsky driver (like was done earlier in this issue), but for some reason tuning to encrypted channels using MythTV also remained stuck in the 'waiting for lock' phase. This was odd as it used to work before. So I tried to comment out the manually added override.conf and suddenly everything started to work again.

Back to the original issue, the segfault in ffdecsawrapper: while experimenting with the media_build kernel modules I found out that the dvb_core module contained some additional kernel parameters. Three of them caught my attention:

dvb_demux_tscheck:enable transport stream continuity and TEI check (int)
dvb_demux_feed_err_pkts:when set to 0, drop packets with the TEI bit set (1 by default) (int)
dvb_powerdown_on_sleep:0: do not power down, 1: turn LNB voltage off on sleep (default) (int)

From what I understand the first one can be used to let the kernel check whether uncorrectable packets were detected and report them in the kernel log. The second one can be used to prevent uncorrectable packets from reaching userspace (i.e. ffdecsawrapper).

The third one sounded interesting to me because I noticed that the tuner sometimes only worked fine on the first scan and failed to tune/lock on subsequent attempts (could also be firmware related).

So I played around with these values and created a file named /etc/modprobe.d/dvb.conf with the following contents: options dvb_core dvb_demux_tscheck=1 dvb_demux_feed_err_pkts=0 dvb_powerdown_on_sleep=0

By filtering out the packets which are 'known broken' I expect that these packets don't reach ffdecsawrapper and therefore ffdecsawrapper can't segfault on junk input any more. Of course this is all theoretical, but I'll leave the situation running for now and see if everything remains stable.

[bas-t]

Well, I lean towards the thought that these broken packages are caused by a broken dvb driver and in turn mess up both userspace and kernel processes (resulting in segfaults and such).

When you filter them out, I think you are just hiding the root cause of your issue(s). That is, assuming your hardware is in good shape and Ziggo did not massively screw up (again).

Anyway, my offer to (try to) fix this driver using the 3.18 media stack still stands. It would not take much time and I love doing this stuff when time permits. Should it succeed, I think it's fun to backport it to 3.10, so you'll be able to compile everything you need in-tree. In-tree being the most solid option. In fact, I hate out of tree drivers and only use them some times for testing purposes.

Should you have to show me any log or lengthy output from dmesg and such in the future, I invite you to use some pastebin service and only paste a link to it here. Cheers, Tycho.

[epienbroek]

I'm fully aware that by letting the kernel driver filter all uncorrectable packets I'm actually masking the root problem (which is likely in the DVB driver). The reason why I did that change was to get to an environment which was mostly working again (instead of a fully broken environment where channel tuning doesn't work) and to determine under what conditions the issue happens. Of course I'm willing to help in testing/debugging when you've got something ready or want me te verify something.

[bas-t]

If this does not fix your driver, I don't know what will... You'll need a fresh clone of the dvbloopback repo using the master branch. Run ./configure --v4l=3.180 and reboot.

The firmware I use is in that repo, look in the 'firmware' dir.

[epienbroek]

Thanks for your work! I just tried to get it compiled, but I'm running into a build failure:

  CC [M]  /root/dvbloopback_new/media_build/v4l/cxusb.o
/root/dvbloopback_new/media_build/v4l/cxusb.c: In function 'cxusb_tt_ct2_4400_attach':
/root/dvbloopback_new/media_build/v4l/cxusb.c:1461:15: error: 'struct si2157_config' has no member named 'if_port'
  si2157_config.if_port = 1;

Full log @ http://fpaste.org/328582/63345281/raw/

[bas-t]

Hm.. strange... I compiled it against a 3.10.97 vanilla kernel and it works (for me). However, I know where to look to fix it for you. That'll be tomorrow.

[bas-t]

Please try again, it should compile ok now.

[epienbroek]

It compiles fine now, thanks! I also reverted my local changes (override.conf and dvb_core module options) so everything should be back to the original clean configuration now.

After the reboot the cxusb module is now used and a quick test has shown that tuning/channel switching works and encrypted channels also get decoded properly. I'll leave things running and do more testing later today but things look good so far :)

[bas-t]

Nice! And it also proves the odroid guy wrong: we don't need the media_controller_dvb.

[bas-t]

Still going strong?

[bas-t]

I just added a final patch to 3.180. Just in case you'd experience anything like glitches or stuttering.

[epienbroek]

There haven't been any segfaults in the last couple of days so that's already a good sign. However, I've noticed that not all recording attempts have been succesful lately. I just tried to schedule a recording on an encrypted channel and for some reason mythtv fails to complete the tuning and starts repeating the following message in an endless loop (that is: until the recorded program is finished according to the EPG):

DTVRec[3]: PES start code not found in TS packet with PUSI set

The odd thing is that it doesn't seem to happen every time. I haven't been able to determine the exact circumstances yet..

I'm uncertain what component is to blame here..OSCAM, FFDecsawrapper, MythTV, the DVB drivers or a bad input signal...

Full logs of all components @ http://fpaste.org/332503/56964303/

[bas-t]

I've been hit by the same issue. It is on a few muxes, all others are ok. I could not find the root cause, so I moved to Tvheadend + Kodi. That solved it for me. Anyhow, the segfault issue seems to be addressed so I'm closing this ticket.

[epienbroek]

Okay, thanks for all the help!

[bas-t]

You're welcome. Should you find the root cause of this new issue, please let me know (I loved mythtv more...) It has something to do with received dvb packets being mangled, swapped bytes or something (marked TEI, so not to be trusted, resulting in wrong pid's, start codes etc.). We can rule out the signal quality and the dvb drivers as root cause, since it works ok with tvheadend.