PIDVR-12: FreeSat adapter is detected but unusable (DVBSky S960)

Issue Information

Issue Type: Bug
 
Priority: Major
Status: Closed

Reported By:
Ben Tasker
Assigned To:
Ben Tasker
Project: PiDVR (PIDVR)
Resolution: Won't Fix (2015-01-21 03:08:57)
Affects Version: Virtualisation specific Issues,
Labels: DVBSkyS960, Passthrough, USB, VirtualBox,

Created: 2014-12-01 12:57:44
Time Spent Working


Description
Following an unknown event in the OS (guest or host?) the FreeSat adapter is presented to the Guest OS but isn't being initialised correctly by the driver.

Dmesg contains the following 

holly kernel: [  659.876236] DVB: registering new adapter (DVBSky S960/S860)
holly kernel: [  661.887998] dvbsky_usb MAC address=00:00:00:00:00:00
holly kernel: [  661.888054] usb 1-1: dvb_usb_v2: MAC address: 00:00:00:00:00:00
holly kernel: [  661.890833] M88DS3103 tuner read stops = 0.
holly kernel: [  663.893311] DS3000 chip version: ffffff92 attached.
holly kernel: [  667.893870] TS202x chip version[1]: ffffff92 attached.
holly kernel: [  671.893335] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x00, value == 0x03)
holly kernel: [  675.909693] TS202x chip version[2]: ffffff92 attached.
holly kernel: [  675.910266] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' error while loading driver (-19)
holly kernel: [  675.912972] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' successfully deinitialized and disconnected



A reset of the USB subsytem (tried in both Guest and Host) didn't work 

for i in $(ls /sys/bus/pci/drivers/ehci_hcd/|grep :);  do echo $i > /sys/bus/pci/drivers/ehci_hcd/unbind;  echo $i > /sys/bus/pci/drivers/ehci_hcd/bind; done


A reboot of the Host also hasn't resolved the issue.


Toggle State Changes

Activity


2014-12-01 12:58:56
Following a powerdown of the Freesat adapter, the adapter still isn't being initialised, but dmesg now contains a little more information 

[    8.505747] usbcore: registered new interface driver dvb_usb_dvbsky
[    8.506972] dvbsky_identify_state, build on Nov 28 2014 05:41:02(),delay=0
[   10.604478] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   10.604810] usb 1-1: dvb_usb_dvbsky: dvbsky_gpio_ctrl() failed=-110
[   12.604274] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   12.604789] usb 1-1: dvb_usb_dvbsky: dvbsky_gpio_ctrl() failed=-110
[   14.710221] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   14.711265] usb 1-1: dvb_usb_dvbsky: dvbsky_gpio_ctrl() failed=-110
[   16.708670] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   16.709646] usb 1-1: dvb_usb_dvbsky: dvbsky_gpio_ctrl() failed=-110
[   16.764141] usb 1-1: dvb_usb_v2: found a 'DVBSky S960/S860' in warm state
[   16.764235] usb 1-1: dvb_usb_v2: will pass the complete MPEG2 transport stream to the software demuxer
[   18.766241] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   18.767322] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   18.767921] dvbsky_usb MAC address=00:00:00:00:00:00
[   18.768497] usb 1-1: dvb_usb_v2: MAC address: 00:00:00:00:00:00
[   20.840232] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   20.840902] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   22.848789] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   22.849316] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   24.848274] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   24.849150] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   26.849707] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   26.851187] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   28.850195] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   28.851247] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   31.108109] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   31.108527] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   33.108842] usb 1-1: dvb_usb_v2: usb_bulk_msg() failed=-110
[   33.109225] usb 1-1: dvb_usb_dvbsky: dvbsky_i2c_xfer() failed=-110
[   33.110352] dvbsky_s960_attach fail.
[   33.110683] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' error while loading driver (-19)
[   33.113705] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' successfully deinitialized and disconnected



2014-12-01 13:02:31
With Host and Guest running,

- Unplugged the USB lead
- Unplugged the power supply

Waited 30 seconds and then reconnected 

[ 1482.721057] dvbsky_identify_state, build on Nov 28 2014 05:41:02(),delay=0
[ 1483.779809] usb 1-1: dvb_usb_v2: found a 'DVBSky S960/S860' in warm state
[ 1483.779904] usb 1-1: dvb_usb_v2: will pass the complete MPEG2 transport stream to the software demuxer
[ 1483.786586] dvbsky_usb MAC address=00:18:42:54:96:0c
[ 1483.786594] usb 1-1: dvb_usb_v2: MAC address: 00:18:42:54:96:0c
[ 1485.360242] m88ds3103_load_firmware: Waiting for firmware upload (dvb-fe-ds3103.fw)...
[ 1485.930054] usb 1-1: firmware: agent loaded dvb-fe-ds3103.fw into memory
[ 1487.568828] Registered IR keymap rc-dvbsky
[ 1487.569604] usb 1-1: dvb_usb_v2: schedule remote query interval to 300 msecs
[ 1487.569610] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' successfully initialized and connected

root@holly:~# ls /dev/dvb/
adapter0


The adapter is now available for use again, though need to try to get to the bottom of exactly why the adapter went away (as having to physically disconnect it isn't practical, and missing recordings because of an unknown issue would be irritating).

2014-12-01 13:07:01
For reference, the complete dmesg output when the adapter is successfully detected is 

[ 1470.221242] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' error while loading driver (-19)
[ 1470.223051] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' successfully deinitialized and disconnected
[ 1478.739235] usb 1-1: USB disconnect, device number 3
[ 1482.536659] usb 1-1: new high-speed USB device number 4 using ehci_hcd
[ 1482.715358] usb 1-1: New USB device found, idVendor=0572, idProduct=6831
[ 1482.715366] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1482.715373] usb 1-1: Product: S960
[ 1482.715380] usb 1-1: Manufacturer: Bestunar
[ 1482.715383] usb 1-1: SerialNumber: 20120511
[ 1482.721057] dvbsky_identify_state, build on Nov 28 2014 05:41:02(),delay=0
[ 1483.779809] usb 1-1: dvb_usb_v2: found a 'DVBSky S960/S860' in warm state
[ 1483.779904] usb 1-1: dvb_usb_v2: will pass the complete MPEG2 transport stream to the software demuxer
[ 1483.779998] DVB: registering new adapter (DVBSky S960/S860)
[ 1483.786586] dvbsky_usb MAC address=00:18:42:54:96:0c
[ 1483.786594] usb 1-1: dvb_usb_v2: MAC address: 00:18:42:54:96:0c
[ 1483.788488] M88DS3103 tuner read stops = 0.
[ 1483.794431] DS3000 chip version: d0 attached.
[ 1483.805340] TS202x chip version[1]: c1 attached.
[ 1484.342287] TS202x chip version[2]: c3 attached.
[ 1485.360242] m88ds3103_load_firmware: Waiting for firmware upload (dvb-fe-ds3103.fw)...
[ 1485.930054] usb 1-1: firmware: agent loaded dvb-fe-ds3103.fw into memory
[ 1485.930061] m88ds3103_load_firmware: Waiting for firmware upload(2)...
[ 1487.496322] usb 1-1: DVB: registering adapter 0 frontend 0 (Montage DS3103/TS2022)...
[ 1487.568828] Registered IR keymap rc-dvbsky
[ 1487.569104] input: DVBSky S960/S860 as /devices/pci0000:00/0000:00:0b.0/usb1/1-1/rc/rc0/input6
[ 1487.569598] rc0: DVBSky S960/S860 as /devices/pci0000:00/0000:00:0b.0/usb1/1-1/rc/rc0
[ 1487.569604] usb 1-1: dvb_usb_v2: schedule remote query interval to 300 msecs
[ 1487.569610] usb 1-1: dvb_usb_v2: 'DVBSky S960/S860' successfully initialized and connected


The first difference that jumps out, is that on the failed entries the device's MAC address is presented as 00:00:00:00:00:00

2014-12-01 13:11:35
Couldn't get TVHeadend to mapp services to channels, and the adapter wouldn't seem to tune to any channel. Have reset TVHeadend's configuration to allow a start from scratch 

root@holly:~# service tvheadend stop
root@holly:~# mv /home/hts/.hts/tvheadend/ /home/hts/.hts/tvheadend.old
root@holly:~# dpkg-reconfigure tvheadend


TVHeadend is currently mapping the MUXes, so can at least talk to the adapter now.

2014-12-01 13:13:44
btasker added 'DVBSkyS960 Passthrough USB VirtualBox' to labels

2014-12-02 13:24:37
At 06:17 this morning, the hardware became unusable again


Guest syslog 
Dec  1 15:26:23 holly kernel: [ 6585.456009] hrtimer: interrupt took 6643400 ns
Dec  2 06:17:34 holly kernel: [60056.521002] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x10, value == 0x0a)
Dec  2 06:17:40 holly kernel: [60062.534612] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x11, value == 0x40)
Dec  2 06:17:48 holly kernel: [60070.534484] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x01, value == 0x00)
Dec  2 06:17:54 holly kernel: [60076.534697] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x02, value == 0xae)
Dec  2 06:17:58 holly kernel: [60080.535023] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x03, value == 0x06)
Dec  2 06:18:04 holly kernel: [60086.534786] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x51, value == 0x0f)
Dec  2 06:18:10 holly kernel: [60092.794722] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x51, value == 0x1f)
Dec  2 06:18:16 holly kernel: [60098.794765] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x50, value == 0x10)
Dec  2 06:18:20 holly kernel: [60102.794726] m88ds3103_tuner_writereg: writereg error(err == -110, reg == 0x50, value == 0x00)



Host's syslog doesn't show anything, and there's nothing around that time in the VirtualBox logs either

2014-12-03 23:40:38
It seems there are a few known issues with the driver, but support should have been added in-kernel since 3.18, so going to ignore the fact it makes me feel dirty and install a Ubuntu kernel


Remove the compiled module 

root@holly:~# cd /usr/src/media_build-bst-13/
root@holly:/usr/src/media_build-bst-13# make rminstall
root@holly:/usr/src/media_build-bst-13# reboot




Check current Kernel version 
root@holly:~# uname -a
Linux holly.home 3.2.0-4-486 #1 Debian 3.2.63-2+deb7u1 i686 GNU/Linux




Grab and install the Ubuntu Kernel 

root@holly:~# wget http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.18-rc1-utopic/linux-headers-3.18.0-031800rc1_3.18.0-031800rc1.201410192135_all.deb
root@holly:~# wget http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.18-rc1-utopic/linux-headers-3.18.0-031800rc1-generic_3.18.0-031800rc1.201410192135_i386.deb
root@holly:~# wget http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.18-rc1-utopic/linux-image-3.18.0-031800rc1-generic_3.18.0-031800rc1.201410192135_i386.deb
root@holly:~# dpkg -i linux-headers-3.18*.deb linux-image-3.18*.deb
root@holly:~# reboot

root@holly:~# modprobe m88ds3103
root@holly:/lib/modules# modprobe m88ts2022



Dmesg gives 

[ 1014.044333] usb 2-1: new full-speed USB device number 2 using ohci-pci
[ 1014.322072] usb 2-1: not running at top speed; connect to a high speed hub
[ 1014.348953] usb 2-1: New USB device found, idVendor=0572, idProduct=6831
[ 1014.348964] usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1014.348971] usb 2-1: Product: S960
[ 1014.348976] usb 2-1: Manufacturer: Bestunar
[ 1014.348981] usb 2-1: SerialNumber: 20120511


Figured a reboot was probably in order to get it back into high speed mode, unfortunately the device now doesn't appear in dmesg at all.

Am also going to compile v4l to see whether that works (and is more stable) than the driver provided by DVBSky

2014-12-04 00:30:13
Building the v4l tree 

root@holly:/media_build# apt-get install git patchutils libproc-processtable-perl
root@holly:/# git clone git://linuxtv.org/media_build.git --depth=1
Cloning into 'media_build'...
remote: Counting objects: 135, done.
remote: Compressing objects: 100% (123/123), done.
remote: Total 135 (delta 13), reused 70 (delta 7)
Receiving objects: 100% (135/135), 182.65 KiB | 120 KiB/s, done.
Resolving deltas: 100% (13/13), done.
root@holly:/# cd media_build/
root@holly:/media_build# ./build 
root@holly:/media_build# make install
root@holly:/media_build# reboot


Which gets us 

[   10.832108] usb 2-1: dvb_usb_v2: found a 'DVBSky S960/S860' in warm state
[   10.832240] usb 2-1: dvb_usb_v2: this USB2.0 device cannot be run on a USB1.1 port (it lacks a hardware PID filter)
[   10.833412] usbcore: registered new interface driver dvb_usb_dvbsky


Does look like Virtualbox has decided to pass it through as a 1.1 device again: 

root@holly:~# lsusb
Bus 002 Device 002: ID 0572:6831 Conexant Systems (Rockwell), Inc. 
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub

2014-12-04 00:39:10
Actually, on the host, it's also showing as a 1.1 device 

[root@starbug ~]# lsusb
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 002: ID 0572:6831 Conexant Systems (Rockwell), Inc. 
Bus 001 Device 003: ID 26bd:9917  
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 002: ID 7392:7711 Edimax Technology Co., Ltd EW-7711UTn nLite Wireless Adapter [Ralink RT2870]
Bus 001 Device 004: ID 04f2:b23b Chicony Electronics Co., Ltd 
Bus 001 Device 005: ID 0bda:0138 Realtek Semiconductor Corp. RTS5138 Card Reader Controller

2014-12-04 00:44:02
Device definitely showing as capable of 2.0 

[root@starbug ~]# lsusb -v -s 1:6

Bus 001 Device 006: ID 0572:6831 Conexant Systems (Rockwell), Inc. 
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0 
  bDeviceProtocol         0 
  bMaxPacketSize0        64
  idVendor           0x0572 Conexant Systems (Rockwell), Inc.
  idProduct          0x6831 
  bcdDevice            0.00
  iManufacturer           1 Bestunar
  iProduct                2 S960
  iSerial                 3 20120511
  bNumConfigurations      1


Will have to play around with it some more later

2014-12-04 00:55:01
Couldn't quite bring myself to give up.....

A reset of the USB subsystem seems to have done it 

[root@starbug ~]# for i in $(ls /sys/bus/pci/drivers/ehci_hcd/|grep :);  do echo $i > /sys/bus/pci/drivers/ehci_hcd/unbind;  echo $i > /sys/bus/pci/drivers/ehci_hcd/bind; done

[root@starbug ~]# lsusb
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 006: ID 0572:6831 Conexant Systems (Rockwell), Inc. 
Bus 001 Device 003: ID 26bd:9917  
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 002: ID 7392:7711 Edimax Technology Co., Ltd EW-7711UTn nLite Wireless Adapter [Ralink RT2870]
Bus 001 Device 004: ID 04f2:b23b Chicony Electronics Co., Ltd 
Bus 001 Device 005: ID 0bda:0138 Realtek Semiconductor Corp. RTS5138 Card Reader Controller




Guest now sees the device as USB2 but something else has gone wrong 

[   10.880735] usb 1-1: dvb_usb_v2: found a 'DVBSky S960/S860' in warm state
[   10.880922] usb 1-1: dvb_usb_v2: will pass the complete MPEG2 transport stream to the software demuxer
[   10.881265] DVB: registering new adapter (DVBSky S960/S860)
[   10.884247] usb 1-1: dvb_usb_v2: MAC address: 00:18:42:54:96:0c
[   10.916900] i2c i2c-0: m88ds3103_attach: chip_id=00
[   10.916938] usb 1-1: dvbsky_s960_attach fail.


No other info in dmesg/syslog.

Giving up for the night I think


2015-01-21 03:08:57
Marking as Won't fix as it doesn't seem worth pursuing virtualisation with this adapter.

See comment in PIDVR-11

2015-01-21 03:08:57
btasker changed status from 'Open' to 'Resolved'

2015-01-21 03:08:57
btasker added 'Won't Fix' to resolution

2015-01-21 03:09:04
btasker changed status from 'Resolved' to 'Closed'