Project

General

Profile

Bug #1643

Auto mux discovery creates mux with incorrect satconf

Added by John Smith over 11 years ago. Updated over 11 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
DVB
Target version:
Start date:
2013-02-24
Due date:
% Done:

100%

Estimated time:
Found in version:
3.5.22~g229a8d7
Affected Versions:

Description

Automatic mux discovery created a mux on incorrect satconf, "Sirius (Viasat)". The mux was created with network "Telenor", ONID=70, TSID=72, which is correct for all parameters on the other satconf in my system.

Could stale data from the previously tuned mux (on other satconf) somehow have been used to create a mux on the currently tuned satconf?

Feb 24 13:26:29 [   INFO]:serviceprobe:                  ETV: checking...
Feb 24 13:26:30 [  DEBUG]:dvb: "/dev/dvb/adapter3" tuning via s2api to "Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))" (1358000, 27500000 Baud, 3/4, SYS_DVBS, QPSK) for Transport start
Feb 24 13:26:30 [  DEBUG]:cwc: TurboSight TBS 6984 DVBS/S2 frontend/Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))/ETV using CWC 127.0.0.1:10003
Feb 24 13:26:30 [  DEBUG]:cwc: TurboSight TBS 6984 DVBS/S2 frontend/Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))/ETV using CWC 127.0.0.1:10002
Feb 24 13:26:30 [   INFO]:subscription: "serviceprobe" direct subscription to adapter: "TurboSight TBS 6984 DVBS/S2 frontend", network: "Viasat", mux: "Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))", provider: "", service: "ETV", quality: 100
Feb 24 13:26:30 [  DEBUG]:Service: TurboSight TBS 6984 DVBS/S2 frontend/Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))/ETV: Status changed to [Hardware input] 
Feb 24 13:26:30 [ NOTICE]:dvb: New mux "Telenor: 10,872,000 kHz Horizontal (Sirius (Viasat))" created by automatic mux discovery
Feb 24 13:26:30 [  DEBUG]:Service: TurboSight TBS 6984 DVBS/S2 frontend/Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))/ETV: Status changed to [Hardware input] [Input on service] 
Feb 24 13:26:30 [  DEBUG]:Service: TurboSight TBS 6984 DVBS/S2 frontend/Viasat: 11,958,000 kHz Horizontal (Sirius (Viasat))/ETV: Status changed to [Hardware input] [Input on service] [Demuxed packets] 

Files

tvhlog_badmux.txt.gz (174 KB) tvhlog_badmux.txt.gz Complete debug log John Smith, 2013-02-25 20:39

History

#1

Updated by Adam Sutton over 11 years ago

  • Category set to DVB

The short answer is yes, possibly. It's been a bit of a concern for a while that data still in the pipelines could be received and processed after the current mux (internal var) has been updated.

Can you pastebin a complete log file, just so I can see a bit more context.

Adam

#2

Updated by John Smith over 11 years ago

Sure. It's a bit big so I attached a zip.

#3

Updated by John Smith over 11 years ago

Looks like I was able to reproduce the mux creation problem while capturing NIT using dvbsnoop. I believe the logs corroborate the stale data theory.

Feb 26 21:48:32 [   INFO]:serviceprobe:       Kanal 5 HD (D): checking...
Feb 26 21:48:34 [  DEBUG]:dvb: "/dev/dvb/adapter3" tuning via s2api to "Telenor: 10,778,000 kHz Vertical (Thor (Canal Digital))" (1028000, 25000000 Baud, 3/4, SYS_DVBS2, PSK_8) for Transport start
Feb 26 21:48:34 [  DEBUG]:cwc: TurboSight TBS 6984 DVBS/S2 frontend/Telenor: 10,778,000 kHz Vertical (Thor (Canal Digital))/Kanal 5 HD (D) using CWC 127.0.0.1:10001
Feb 26 21:48:34 [  DEBUG]:Service: TurboSight TBS 6984 DVBS/S2 frontend/Telenor: 10,778,000 kHz Vertical (Thor (Canal Digital))/Kanal 5 HD (D): Status changed to [Hardware input] 
Feb 26 21:48:34 [   INFO]:subscription: "serviceprobe" direct subscription to adapter: "TurboSight TBS 6984 DVBS/S2 frontend", network: "Telenor", mux: "Telenor: 10,778,000 kHz Vertical (Thor (Canal Digital))", provider: "Telenor", service: "Kanal 5 HD (D)", quality: 100
Feb 26 21:48:34 [ NOTICE]:dvb: New mux "Sirius: 12,379,620 kHz Horizontal (Thor (Canal Digital))" created by automatic mux discovery
Feb 26 21:48:34 [ NOTICE]:dvb: New mux "Sirius: 11,842,560 kHz Horizontal (Thor (Canal Digital))" created by automatic mux discovery
Feb 26 21:48:34 [ NOTICE]:dvb: New mux "Sirius: 12,245,000 kHz Vertical (Thor (Canal Digital))" created by automatic mux discovery
Feb 26 21:48:34 [ NOTICE]:dvb: New mux "Sirius: 11,900,000 kHz Vertical (Thor (Canal Digital))" created by automatic mux discovery
Feb 26 21:48:34 [ NOTICE]:dvb: New mux "Sirius: 11,958,000 kHz Horizontal (Thor (Canal Digital))" created by automatic mux discovery
------------------------------------------------------------
SECT-Packet: 00007547   PID: 16 (0x0010), Length: 344 (0x0158)
Time received: Tue 2013-02-26  21:48:33.139
------------------------------------------------------------
PID:  16 (0x0010)  [= assigned for: DVB Network Information Table (NIT), Stuffing Table (ST)]

Guess table from table id...
NIT-decoding....
Table_ID: 64 (0x40)  [= Network Information Table (NIT) - actual network]

<...snip...>

    Transport_stream_ID: 2 (0x0002)
    Original_network_ID: 85 (0x0055)  [= Sirius Satellite System European Coverage | NSAB (Teracom)]
    reserved_1: 15 (0x0f)
    Transport_descriptor_length: 54 (0x0036)

            DVB-DescriptorTag: 67 (0x43)  [= satellite_delivery_system_descriptor]
            descriptor_length: 11 (0x0b)
            Frequency: 19102050 (=  12.37962 GHz)
            Orbital_position: 80 (=   5.0)
            West_East_flag: 1 (0x01)  [= EAST]
            Polarisation: 0 (0x00)  [= linear - horizontal]
            Kind: 0 (0x00)  [= DVB-S]
            fixed ('00'): 0 (0x00)
            Modulation_type: 1 (0x01)  [= QPSK]
            Symbol_rate: 2576384 (=  27.5000)
            FEC_inner: 3 (0x03)  [= 3/4 conv. code rate]

A bit more context can be found in the pastebins below.

TVH log snippet:
http://pastebin.com/ncspSCWm

dvbsnoop snippet:
http://pastebin.com/2q639Xgj

#4

Updated by Adam Sutton over 11 years ago

  • Status changed from New to Accepted
  • Target version set to 3.4
  • Affected Versions 3.4 added

I'd really appreciate it if you can try this patch:
http://pastebin.com/Ut4WLcuA

It'll close the dvr device on each re-tune, this will hopefully stop stale data from being in the pipeline (I hope!).

Adam

#5

Updated by Adam Sutton over 11 years ago

  • Status changed from Accepted to Fixed
  • % Done changed from 0 to 100

Applied in changeset commit:55ed28cb53307f77c7c767cd6f87f56b15951bcd.

#6

Updated by John Smith over 11 years ago

I've been running the patch for 36 hours now and was just about to confirm it fixed the issue as no bad muxes were added. (Typically I'll get bad muxes in a 4h run.)

When trying to watch a channel though I noticed I now always seem to get "Graceperiod Expired". Adapter bandwidth shows 0kb/s so maybe there's no data at all coming through which could also explain no bad muxes. "Graceperiod Expired" issue is discussed here:
https://www.lonelycoder.com/redmine/boards/5/topics/7037?r=7880

#7

Updated by John Smith over 11 years ago

Isn't this patch missing something like a dvb_adapter_start_dvr() to re-open the dvr device again after closing on each re-tune?

#8

Updated by John Smith over 11 years ago

I pulled from git last night and built 3.5.52~g819b8c8. Unfortunately I still got a bad mux created when running over night.

Mar 12 05:42:49 [  DEBUG]:dvb: /dev/dvb/adapter3 started dvr thread
Mar 12 05:42:51 [  DEBUG]:dvb: "/dev/dvb/adapter3" tuning via s2api to "Viasat: 12,284,000 kHz Vertical (Sirius (Viasat))" (1684000, 27500000 Baud, 3/4, SYS_DVBS, QPSK) for Autoscan
Mar 12 05:42:55 [  DEBUG]:dvb: Configuration for mux "SIRIUS: 12,284,000 kHz Vertical (Sirius (Viasat))" updated by automatic mux discovery
Mar 12 05:43:09 [  DEBUG]:dvb: /dev/dvb/adapter3 stopping thread
Mar 12 05:43:09 [  DEBUG]:dvb: /dev/dvb/adapter3 stopped thread
Mar 12 05:43:09 [  DEBUG]:dvb: /dev/dvb/adapter3 started dvr thread
Mar 12 05:43:11 [  DEBUG]:dvb: "/dev/dvb/adapter3" tuning via s2api to "Telenor: 10,872,000 kHz Horizontal (Thor (Canal Digital))" (1122000, 25000000 Baud, 3/4, SYS_DVBS2, PSK_8) for Autoscan
Mar 12 05:43:11 [ NOTICE]:dvb: New mux "SIRIUS: 12,283,700 kHz Vertical (Thor (Canal Digital))" created by automatic mux discovery
Mar 12 05:43:11 [  DEBUG]:PSI: Service "TurboSight TBS 6984 DVBS/S2 frontend/Telenor: 10,872,000 kHz Horizontal (Thor (Canal Digital))/Yle TV1" PMT (version 9) updated, Stream deleted, PIDs reordered
Mar 12 05:43:12 [  DEBUG]:dvb: /dev/dvb/adapter3 stopping thread
Mar 12 05:43:12 [  DEBUG]:dvb: /dev/dvb/adapter3 stopped thread
Mar 12 05:43:12 [  DEBUG]:dvb: /dev/dvb/adapter3 started dvr thread
#9

Updated by John Smith over 11 years ago

Have you seen this, "full TS in Linux: known issue or new one?"?
http://thread.gmane.org/gmane.linux.drivers.video-input-infrastructure/19432

Not sure if it's old and fixed or what the status is but I just tried the attached script and confirmed my expectation. I'm getting thousands of TS packets from the last tuned mux before getting good data from the new mux. Maybe this issue isn't a TVH bug after all but a Linux or TBS problem? Most likely a real problem for TVH users either way.

#10

Updated by Adam Sutton over 11 years ago

John,

Thanks for that link, this is what I'd long feared was the problem but no one could definitively answer whether or not we thought this would happen. I had already suggested that we should discard at least the SI table data for a small period of time immediately after locking.

I'll read that thread fully and see what ideas others have.

Adam

#11

Updated by John Smith over 11 years ago

I haven't been able to let this one go and I found this ancient thread:
http://www.linuxtv.org/mailinglists/linux-dvb/2004/05-2004/msg00254.html

"Full ACK. The frontend API is specified to be asynchronous, if userland sets filters before the frontend reports successful tuning it's its own fault"

I wrote a simple test program and I have not been able to reproduce the stale data if the demuxer is configured after tuning. If I configure the demuxer before tuning, I get lots of data from the "last" (actually currently) tuned mux before tuning has been updated. This might actually start to make sense and there may be an elegant solution after all.

dvb_fe_tune() first calls dvb_fe_stop() to flush the pipes it then calls dvb_adapter_start() before frontend tuning is done. dvb_adapter_start() will start the dvr thread. The dvr thread will configure the demuxer. I'm guessing the dvr thread is up and running with configured demuxer before the new tuning is done, filling the recently flushed buffers again. Makes sense?

The solution would be to make sure that tuning is initiated and lock has been confirmed before the demuxer is configured.

#12

Updated by Adam Sutton over 11 years ago

That's interesting, I actually wrote the code to work like that a few days ago while I was messing about. But I didn't commit it as I was just hacking. I put a "wait for lock" loop in the dvr_adapter_input_dvr() routine. I'll have a look at doing a cleaner solution and if you could test that I'd really appreciate it.

Adam

#13

Updated by Adam Sutton over 11 years ago

Can you try this, its a bit of a hack. It blocks the tune process until lock, this is a horrible hack as its done while holding the global lock so slow tuning will wreak havoc with performance! Also its untested ;)

If that appears to do the business though I'll have a re-think about how best to handle the tuning at the fact we need to handle the async nature better than we do.

http://pastebin.com/raw.php?i=YZkBSYWy

Adam

#14

Updated by John Smith over 11 years ago

Sure. It's running now and I'll check for bad muxes in the morning.

I had to hardcode count to avoid it being 0.

count  = 100;// * tda->tda_grace_period; 

#15

Updated by Adam Sutton over 11 years ago

Ah yes, forgot that was zero by default.

Adam

#16

Updated by Adam Sutton over 11 years ago

  • Status changed from Fixed to Accepted

I've done a reworking of how the adapter tune/startup works, I'll try that on my own rig when I get a chance.

Adam

#17

Updated by John Smith over 11 years ago

Sorry to say I still had new bad muxes this morning. (Possibly with lower failure rate.)

I've been looking at the code some more today. Is the tda_table_feed queue flushed anywhere?

#18

Updated by Adam Sutton over 11 years ago

No it doesn't, I hadn't spotted that as I saw a flush call to the table code, but it turns out this will not flush the raw feed Q as you rightly point out.

Try this:

http://pastebin.com/raw.php?i=Q2wfDdpw

It should ensure that Q is emptied on fe_stop().

Adam

#19

Updated by John Smith over 11 years ago

I applied it on top of your earlier "horrible hack" and restarted. I'll check again tomorrow. It took 7h last night before I got a bad mux created.

#20

Updated by Adam Sutton over 11 years ago

ta

I've actually done a proper reworking of the code, though it needs some testing and thinking through (to make sure its right). So "if" this looks good then I'll add this minor mod and think about pushing to master.

Adam

#21

Updated by John Smith over 11 years ago

Good news. No bad muxes this morning after 18h. Looks like this might have done it even if it's not 100% guaranteed.

There's a deadlock on tda_delivery_mutex when subscribing to a service though. dvb_service_start() calls dvb_fe_tune() with the mutex already locked.

#22

Updated by Adam Sutton over 11 years ago

  • Status changed from Accepted to Fixed

Applied in changeset commit:ddc466c1bfa7405563a68a662114f5a3659d7cb5.

Also available in: Atom PDF