scanning for channels gets stuck on "_open_file"

[grkblood13]

Built on raspberry pi 4 running nodejs v14.

Build instructions:
git clone https://github.com/mkrufky/libdvbtee.git
cd libdvbtee
./build-auto.sh
sudo cp -rp dvbtee /opt/
sudo ln -s /opt/dvbtee/dvbtee /usr/local/bin

Command to scan:
dvbtee -s -a0 > out.tmp

Results:
scan appears to run but gets stuck on the following line, resulting in a file with only "# dvbtee v0.6.7 - http://github.com/mkrufky/libdvbtee" written at the top.

...
store PMT: v14, service_id 3, pcr_pid 49
es_pid | type
31 | 0x02 (Video MPEG-2) |
34 | 0x81 (Audio AC3 (ATSC)) | eng
35 | 0x81 (Audio AC3 (ATSC)) | spa
store PMT: v14, service_id 5, pcr_pid 81
es_pid | type
51 | 0x02 (Video MPEG-2) |
54 | 0x81 (Audio AC3 (ATSC)) | eng
scan channel 26...
tuned to 545000000
scan channel 27...
tuned to 551000000
SCVYL start_feed: using /dev/dvb/adapter0/demux0
_open_file: using /dev/dvb/adapter0/dvr0

[mkrufky]

@grkblood13 What device did you use for the ATSC capture? Also, do you know the exact kernel version? Is there any relevant info in the corresponding dmesg logs?

[grkblood13]

device:
Hauppauge WinTV-HVR-950Q
https://www.linuxtv.org/wiki/index.php/Hauppauge_WinTV-HVR-950Q

kernel info:
Linux raspberrypi 4.19.118-v7l+ #1311 SMP Mon Apr 27 14:26:42 BST 2020 armv7l GNU/Linux

dmesg:
[ 85.699965] usb 1-1.3: new high-speed USB device number 6 using xhci_hcd
[ 85.830291] usb 1-1.3: config 1 interface 0 altsetting 0 endpoint 0x81 has invalid wMaxPacketSize 0
[ 85.852449] usb 1-1.3: New USB device found, idVendor=2040, idProduct=7200, bcdDevice= 0.05
[ 85.852465] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=10
[ 85.852478] usb 1-1.3: Product: WinTV HVR-950
[ 85.852491] usb 1-1.3: Manufacturer: Hauppauge
[ 85.852503] usb 1-1.3: SerialNumber: 4032701650
[ 86.260379] au0828: i2c bus registered
[ 86.312087] tveeprom: Hauppauge model 72001, rev B3F0, serial# 4032701650
[ 86.312098] tveeprom: MAC address is 00:0d:fe:5e:24:d2
[ 86.312110] tveeprom: tuner model is Xceive XC5000 (idx 150, type 76)
[ 86.312124] tveeprom: TV standards NTSC(M) ATSC/DVB Digital (eeprom 0x88)
[ 86.312135] tveeprom: audio processor is AU8522 (idx 44)
[ 86.312145] tveeprom: decoder processor is AU8522 (idx 42)
[ 86.312155] tveeprom: has no radio, has IR receiver, has no IR transmitter
[ 86.312167] au0828: hauppauge_eeprom: hauppauge eeprom: model=72001
[ 86.324442] au8522 7-0047: creating new instance
[ 86.324456] au8522_decoder creating new instance...
[ 86.337661] tuner: 7-0061: Tuner -1 found with type(s) Radio TV.
[ 86.337777] xc5000 7-0061: creating new instance
[ 86.342840] xc5000: Successfully identified at address 0x61
[ 86.342851] xc5000: Firmware has not been loaded previously
[ 86.542774] au8522 7-0047: attaching existing instance
[ 86.544677] xc5000 7-0061: attaching existing instance
[ 86.548435] xc5000: Successfully identified at address 0x61
[ 86.548439] xc5000: Firmware has not been loaded previously
[ 86.548444] dvbdev: DVB: registering new adapter (au0828)
[ 86.548453] usb 1-1.3: DVB: registering adapter 0 frontend 0 (Auvitek AU8522 QAM/8VSB Frontend)...
[ 86.633043] Registered IR keymap rc-hauppauge
[ 86.633150] rc rc0: au0828 IR (Hauppauge HVR950Q) as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/rc/rc0
[ 86.633385] rc rc0: lirc_dev: driver au0828-input registered at minor = 0, raw IR receiver, no transmitter
[ 86.633467] input: au0828 IR (Hauppauge HVR950Q) as /devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.3/rc/rc0/input3
[ 86.635171] au0828: Remote controller au0828 IR (Hauppauge HVR950Q) initialized
[ 86.635176] au0828: Registered device AU0828 [Hauppauge HVR950Q]
[ 148.441063] xc5000: Firmware dvb-fe-xc5000-1.6.114.fw loaded and running.

[mkrufky]

So, no errors in the logs that correspond to the freeze? Is this a new problem introduced by this kernel version or does it happen with older kernels? I will see if i can reproduce it.

Have you tried enabling debug on dvbtee ? Try passing -d 511 Maybe the debug shows what's happening...

[grkblood13]

When running in debug mode the command returns as expected. When I remove the debug flag it returns to hanging. Do you want the debug log? Not sure how much it'll help since it runs properly when setting the flag.

[grkblood13]

I just received the RPI4, so I have no insight on how it ran on older kernels on the pi.

[mkrufky]

I think I've seen this before, but I thought I had fixed it at the kernel level. I will try to repro, but I don't (yet) have an rpi4 -- thanks for the reminder, I will order one.

It sounds like either a race condition or a deadlock .... or a deadlock caused by a race condition.

Does anything else get you past it other than enabling debug?

[grkblood13]

I was able to run twice successfully without debug mode and then another hang on the third attempt. Perhaps the hang is related to these libdvbpsi errors that seem to be unpredictable as we're dealing with a live environment.

This is probably a similar situation to the last bug I opened and subsequently closed after having problems reproducing: #57

Error: libdvbpsi error (PSI decoder): TS discontinuity (received 14, expected 4) for PID 128
Error: libdvbpsi error (PSI decoder): TS discontinuity (received 1, expected 7) for PID 144
Error: libdvbpsi error (PSI decoder): TS discontinuity (received 4, expected 15) for PID 8187
....................................Error: libdvbpsi error (PSI decoder): TS discontinuity (received 3, expected 2) for PID 144
store PMT: v1, service_id 8, pcr_pid 161
es_pid | type
a1 | 0x02 (Video MPEG-2) |
a4 | 0x81 (Audio AC3 (ATSC)) | eng
store PMT: v1, service_id 9, pcr_pid 177
es_pid | type
b1 | 0x02 (Video MPEG-2) |
b4 | 0x81 (Audio AC3 (ATSC)) | eng
Error: libdvbpsi error (PSI decoder): TS discontinuity (received 9, expected 1) for PID 192
store PMT: v1, service_id 11, pcr_pid 209
es_pid | type
d1 | 0x02 (Video MPEG-2) |
d4 | 0x81 (Audio AC3 (ATSC)) | eng
Error: libdvbpsi error (PSI decoder): TS discontinuity (received 10, expected 9) for PID 8187
.....scan channel 13...
tuned to 213000000
scan channel 14...
tuned to 473000000
scan channel 15...
tuned to 479000000
scan channel 16...
tuned to 485000000
scan channel 17...
tuned to 491000000
SCVYL start_feed: using /dev/dvb/adapter0/demux0
_open_file: using /dev/dvb/adapter0/dvr0

[grkblood13]

seems to be related to the errors listed above. seeing same behavior on multiple runs after further testing.

good run -> https://gist.github.com/grkblood13/425d2d2ad2d8282b5c2d420e83a21a4c
bad run -> https://gist.github.com/grkblood13/b620f79ad8290aa11568021d1e8be412

[mkrufky]

I notice the hang is on a different frequency from what you posted previously. Is this the only tuner stick you have? It looks like a driver issue, but it still could be the app.

I can try to repro over the weekend using my desktop.