no data sent for more than 1s

9000h commented 4 years ago

https://github.com/catalinii/minisatip/blob/f4a3400980a803e014ed29deee451121f47f7e70/src/stream.c#L1184-L1189 I do have some times "no data sent .." in my logs but there is data coming from the dmx, it seems in my setup it need at least up to 1.23s. I did increase the check to 1.5s and now it's not happen again.

9000h commented 4 years ago

I believe mainly VDR is the client with his epg/eit background scan, and happen only on orphaned channels in the channels.conf . The SAT>IP spec has no way report this in a way the client gives up the request, maybe reporting no LOCK in signal can help.

lars18th commented 4 years ago

Hi,

To check if the problem is this: "you do not send data from legitimate reasons" , then I suggest this simple test:

Incorporate a simple debug line that printouts in the log if the pids list associated to a running stream is empty.

The only one case in that is true that is a ligitimate reason to not send any data from the tuner is when the pid list is empty. And with this debug it's possible to detect it.

So, if this is the cause of the trouble, then I suggest this simple workaround: if the pid list is empty, then enforce to send the pid 0. This will never create any trouble with any SAT>IP client.

You agree?

9000h commented 4 years ago

If I'm not wrong the pid 0 get added already but if you tune to a freq with no valid content this will not help. https://github.com/catalinii/minisatip/blob/c6fa544f386acb9d14f7da74b43c89e4bce0d007/src/adapter.c#L930

lars18th commented 4 years ago

Hi @9000h ,

Two different cases:

When a not valid freq is requested, then the tuner will not lock. And in this case, the RTP stream is empty and the RTSP stream indicates "no lock, no signal". And the current code is right for this case.
When a client starts a PLAY and the pid list is empty, then the SAT>IP server requires to put some pid in the list. And for this reason the code you pointed adds the pid 0 to it. So another time the current code is right for this case too.

However, another different case is related to point 2. That's when the SAT>IP client removes all pids from a running stream. In this case, the code you pointed is not used. And is the case I suggest to log. For sure this is an edge case, and no single client should generate it. However, it's possible that some especial client that is reading for example only the EIT time to time, can leave the stream without pids at some point. The best solution in the client part, is to add every time the pid 0. However, the server can do it simillary and include the pid 0 if the pid list goes empty.

Please, do the test. It's quite easy to know if the pid list changes to an empty state when the stream continues running.

Regards.

9000h commented 4 years ago

Hi, in this case its https://www.satindex.de/frequenz/11494/

Jan 19 23:11:53 localhost minisatip[7078]: [19/01 23:11:53.628 signal]: get_signal_new took 3 ms for adapter 0 handle 10 (status: 3, ber: 0, strength:254, snr: 43, force scan 0)

it seem to bee to fast and has no LOCK and get reported right to the client, but reading from the dmx without a LOCK will fail

Jan 19 22:47:10 localhost minisatip[7078]: [19/01 22:47:10.705 signal]: get_signal_new took 213 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 38, force scan 0)
Jan 19 22:47:15 localhost minisatip[7078]: [19/01 22:47:15.004 main]: tuning to 554000000 delsys: dvbt2 bw:8000000 inversion:  mod:qpsk fec:  guard:19128 transmission: 16k, ts clear = 3927263
Jan 19 22:47:15 localhost minisatip[7078]: a=fmtp:33 ver=1.1;tuner=5,0,0,0,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=
Jan 19 22:47:16 localhost minisatip[7078]: a=fmtp:33 ver=1.1;tuner=5,87,1,0,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=
Jan 19 22:47:19 localhost minisatip[7078]: [19/01 22:47:19.762 main]: tuning to 578000000 delsys: dvbt2 bw:8000000 inversion:  mod:qpsk fec:  guard:19128 transmission: 16k, ts clear = 3932022
Jan 19 22:47:19 localhost minisatip[7078]: a=fmtp:33 ver=1.1;tuner=5,0,0,0,578.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=
Jan 19 22:47:23 localhost minisatip[7078]: [19/01 22:47:23.532 main]: tuning to 554000000 delsys: dvbt2 bw:8000000 inversion:  mod:qpsk fec:  guard:19128 transmission: 16k, ts clear = 3935792
Jan 19 22:47:23 localhost minisatip[7078]: a=fmtp:33 ver=1.1;tuner=5,0,0,0,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=
Jan 19 22:47:28 localhost minisatip[7078]: [19/01 22:47:28.378 main]: tuning to 554000000 delsys: dvbt2 bw:8000000 inversion:  mod:qpsk fec:  guard:19128 transmission: 16k, ts clear = 3940638
Jan 19 22:47:28 localhost minisatip[7078]: a=fmtp:33 ver=1.1;tuner=5,0,0,0,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=
Jan 19 22:47:41 localhost minisatip[7078]: [19/01 22:47:41.349 main]: tuning to 570000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 3953609
Jan 19 22:47:41 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,570.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 22:47:44 localhost minisatip[7078]: [19/01 22:47:44.690 main]: tuning to 570000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 3956950
Jan 19 22:47:44 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,570.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 22:47:48 localhost minisatip[7078]: [19/01 22:47:48.519 main]: tuning to 586000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 3960779
Jan 19 22:47:48 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,586.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 22:48:02 localhost minisatip[7078]: [19/01 22:48:02.925 main]: tuning to 586000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 3975185
Jan 19 22:48:02 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,586.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 23:11:52 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,255,1,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:11:52 localhost minisatip[7078]: [19/01 23:11:52.524 main]: tuning to 11494000(984000) pol: h (2) sr:22000000 fec:23 delsys:dvbs2 mod:8psk rolloff:0.35 pilot: , ts clear=5404581, ts pol=5404590
Jan 19 23:11:53 localhost minisatip[7078]: [19/01 23:11:53.628 signal]: get_signal_new took 3 ms for adapter 0 handle 10 (status: 3, ber: 0, strength:254, snr: 43, force scan 0)
Jan 19 23:11:54 localhost minisatip[7078]: [19/01 23:11:54.433 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:01 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,0,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:01 localhost minisatip[7078]: [19/01 23:12:01.951 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:02 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,0,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:02 localhost minisatip[7078]: [19/01 23:12:02.954 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:03 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,0,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:04 localhost minisatip[7078]: [19/01 23:12:04.057 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:04 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,0,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:05 localhost minisatip[7078]: [19/01 23:12:05.160 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:05 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,0,15,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:06 localhost minisatip[7078]: [19/01 23:12:06.363 AD0]: no data sent for more than 1s sid: 0 for 192.168.178.114:39150
Jan 19 23:12:06 localhost minisatip[7078]: [19/01 23:12:06.584 main]: tuning to 11362000(984000) pol: h (2) sr:22000000 fec:23 delsys:dvbs2 mod:8psk rolloff:0.35 pilot: , ts clear=5418650, ts pol=5418650
Jan 19 23:12:07 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,0,0,0,11362,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:07 localhost minisatip[7078]: [19/01 23:12:07.301 signal]: get_signal_new took 313 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 38, force scan 0)
Jan 19 23:12:17 localhost minisatip[7078]: [19/01 23:12:17.224 main]: tuning to 11494000(984000) pol: h (2) sr:22000000 fec:23 delsys:dvbs2 mod:8psk rolloff:0.35 pilot: , ts clear=5429283, ts pol=5429289
Jan 19 23:12:17 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,0,0,0,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:17 localhost minisatip[7078]: [19/01 23:12:17.984 signal]: get_signal_new took 210 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 43, force scan 0)
Jan 19 23:12:18 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,1,2,11494,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:20 localhost minisatip[7078]: [19/01 23:12:20.396 main]: tuning to 11362000(984000) pol: h (2) sr:22000000 fec:23 delsys:dvbs2 mod:8psk rolloff:0.35 pilot: , ts clear=5432384, ts pol=5432461
Jan 19 23:12:20 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,0,0,0,11362,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:21 localhost minisatip[7078]: [19/01 23:12:21.157 signal]: get_signal_new took 210 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 38, force scan 0)
Jan 19 23:12:21 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,1,2,11362,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:22 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=1,255,1,15,450.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 23:12:23 localhost minisatip[7078]: [19/01 23:12:23.195 main]: tuning to 450000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 5435456
Jan 19 23:12:27 localhost minisatip[7078]: [19/01 23:12:27.436 main]: tuning to 11303000(984000) pol: h (2) sr:22000000 fec:23 delsys:dvbs2 mod:8psk rolloff:0.35 pilot: , ts clear=5439500, ts pol=5439500
Jan 19 23:12:27 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,0,0,0,11303,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:28 localhost minisatip[7078]: [19/01 23:12:28.209 signal]: get_signal_new took 212 ms for adapter 0 handle 10 (status: 31, ber: 0, strength:254, snr: 38, force scan 0)
Jan 19 23:12:28 localhost minisatip[7078]: a=fmtp:33 ver=1.0;src=1;tuner=1,254,1,2,11303,h,dvbs2,8psk,,0.35,22000,23;pids=
Jan 19 23:12:34 localhost minisatip[7078]: [19/01 23:12:34.070 main]: tuning to 570000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 5446331
Jan 19 23:12:34 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,570.00,8,dvbc,256qam,6900,0,,,;pids=
Jan 19 23:12:36 localhost minisatip[7078]: [19/01 23:12:36.405 main]: tuning to 570000000 sr:6900000 specinv:  delsys:dvbc mod:256qam ts clear = 5448666
Jan 19 23:12:36 localhost minisatip[7078]: a=fmtp:33 ver=1.2;tuner=7,0,0,0,570.00,8,dvbc,256qam,6900,0,,,;pids=

get_signal_new took 3 ms for adapter 0 handle 10 (status: 3, ber: 0, strength:254, snr: 43, force scan 0) status 3 is FE_HAS_SIGNAL | FE_HAS_FE_CARRIER but it gets no FE_HAS_LOCK from the driver

https://github.com/catalinii/minisatip/blob/de38af408d8f511611f078ccc1ea40b43e8bf06a/src/dvb.h#L59-L68

lars18th commented 4 years ago

Hi @9000h ,

get_signal_new took 3 ms for adapter 0 handle 10 (status: 3, ber: 0, strength:254, snr: 43, force scan 0) status 3 is FE_HAS_SIGNAL | FE_HAS_FE_CARRIER but it gets no FE_HAS_LOCK from the driver

Then the problem is insufficient signal in the tuner. In this case, the current behaviour is the expected one. So you need to check your antenna and/or wire.

In any case, if you want to improve your system, then try to request about the drivers you use. I belive if the tuner has some signal even if it is not locked, it can output some packets with errors. And in this case, a corrupted TS packet (with correct error flag in the header) is preferable to nothing.

Regards.

Note: Only to comment about the different behaviours when some errors appear in the tuner... My SAT>IP server (a low cost STB) when it detects some error in the incoming stream instead of seding the packet with the error flags, it removes it. So with small errors in the bitstream from the antenna will generate multiple CC errors in the minisatip satipc module. And then the final SAT>IP client suffers a lot of glitches. All because of a weak implementation on the SAT>IP server.

9000h commented 4 years ago

@catalinii will try to show the real issue with a example you may can replicate by youself, so do start a the following channels real short after each other this is a non working channel on Astra 19.2

wget "http://192.168.178.129:8080/?src=1&freq=12343&pol=h&ro=0.35&msys=dvbs2&mtype=8psk&plts=on&sr=27500&fec=34&pids=0,17,18,518,90,8190,1817" -O /dev/null

CTRL-C than start a working channel on Astra 19.2

wget "http://192.168.178.129:8080/?src=1&freq=11494&pol=h&ro=0.35&msys=dvbs2&mtype=8psk&plts=on&sr=22000&fec=23&pids=0,17,18,5100,5101,5102,5104" -O /dev/null

the correspondent log syslog.txt.gz so you see the second channel will not tune right and the stream will fail, so it seems the adapter is blocked somehow up to a timeout.

lars18th commented 4 years ago

Hi @9000h ,

So you say that your test desmonstrates that if a SAT>IP client requests a non-existent channel inside an active transponder then the internal state machine of minisatip is blocking the running stream because no PMT is readed? It's that true?

9000h commented 4 years ago

I would show, when the client has already left the stream for the bad channel the adapter is unusable for some time which should not happen.

9000h commented 4 years ago

the only major difference is the unicable hiband = 1 for the first tune and hiband = 0 for the second but this is may be unrelated as it happens also for DVB-C

9000h commented 4 years ago

if I comment out the repeated switch_setup in dvb.c, the test https://github.com/catalinii/minisatip/issues/660#issuecomment-576641088 looks good here for DVB-S2 and my Inverto Unicable switch (Inverto Unicable II IDLU-UWT110-CUO1O-32P) https://github.com/catalinii/minisatip/blob/7f1987f07ae880cd34e465101687de9c6d2262af/src/dvb.c#L1573-L1578

this may did mess up the switch slot somehow here, hmm

for VDR it did also help, but still investigating the "no data" get's logged on the bad channel, but that's fine and right, switching to a working channel did work immediately and will not end up in black screen.

so the repeated switch setup mess it up, so it's probably a timing issue or the repeat is not needed at least for my setup

for DVB-C/T2 the "no data" on a bad channel is also happen and normal

9000h commented 4 years ago

looks like the code was added here https://github.com/catalinii/minisatip/commit/4669f808677ade818a2592605f03c856abe9ee22 https://github.com/catalinii/minisatip/issues/313

9000h commented 4 years ago

I would suggest removing this part of the code. https://github.com/catalinii/minisatip/blob/7f1987f07ae880cd34e465101687de9c6d2262af/src/dvb.c#L1573-L1578

9000h commented 4 years ago

I do mean this serious, as this part of the code did harm the communication between the card and the unicable slot in way that the adapter is unusable for certain amount of time as the switch may defend itself.

any comments?

catalinii commented 4 years ago

Basically you are saying that there is a problem doing the switch setup multiple times? As I do not see an error on how the switch commands are handled.

This patch was added because some UNICABLE switches needs some time to boot up. By sending the commands multiple times, by the time they are up they will receive the correct command.

9000h commented 4 years ago

yes my Unicable switch do no like it, but the here issue is a different one, it's not the fist tune issue with unpowered Unicable LNB's/switches.

9000h commented 4 years ago

not sure how to solve both conditions for unicable/jess bad switch/lnb needs the repeat, I cannot test this unneeded repeats for getting no lock on bad/non-existing freq/transponder, I can test/prove it.

catalinii commented 4 years ago

Can you try with the latest master?

9000h commented 4 years ago

did not compile :-(

adapter.c: In function ‘signal_thread’:
adapter.c:2103:16: error: ‘SMutex {aka struct struct_mutex}’ has no member named ‘mutex_state’
   if (ad->mutex.mutex_state != 0)
                ^

should it be not if (ad->mutex.state != 0)

9000h commented 4 years ago

but seem to fix it!

9000h commented 4 years ago

it did improve the behavior but my switch still dont like the repeat, but there is still something else like Jan 29 10:55:56 localhost minisatip[23809]: [29/01 10:55:56.261 signal]: get_signal_new took 1352 ms for adapter 0 handle 8 (status: -1, ber: 0, strength:0, snr: 0, force scan 0)

Jan 29 10:55:50 localhost minisatip[23809]: [29/01 10:55:50.695 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:50 localhost minisatip[23809]: [29/01 10:55:50.892 signal]: get_signal_new took 242 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:50 localhost minisatip[23809]: [29/01 10:55:50.996 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:50 localhost minisatip[23809]: [29/01 10:55:50.996 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:51 localhost minisatip[23809]: [29/01 10:55:51.193 signal]: get_signal_new took 200 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:51 localhost minisatip[23809]: [29/01 10:55:51.867 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:51 localhost minisatip[23809]: [29/01 10:55:51.868 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:52 localhost minisatip[23809]: [29/01 10:55:52.064 signal]: get_signal_new took 672 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:52 localhost minisatip[23809]: [29/01 10:55:52.168 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:52 localhost minisatip[23809]: [29/01 10:55:52.168 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:52 localhost minisatip[23809]: [29/01 10:55:52.364 signal]: get_signal_new took 200 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.031 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.032 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.228 signal]: get_signal_new took 664 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.332 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.332 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:53 localhost minisatip[23809]: [29/01 10:55:53.528 signal]: get_signal_new took 200 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.212 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.212 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.409 signal]: get_signal_new took 680 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.512 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.512 signal]: send_unicable fd 8, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 29 10:55:54 localhost minisatip[23809]: [29/01 10:55:54.708 signal]: get_signal_new took 200 ms for adapter 0 handle 8 (status: 0, ber: 0, strength:255, snr: 248, force scan 0)
Jan 29 10:55:55 localhost minisatip[23809]: [29/01 10:55:55.364 signal]: get_signal_new adapter 0: status 0, strength -380 dBm -> 65285, snr -3000 dB -> -1966, BER: 0, err 0
Jan 29 10:55:55 localhost minisatip[23809]: [29/01 10:55:55.562 signal]: send_unicable fd 8, freq 1744, ufreq 984, pos = 0, pol = 1, hiband = 0, slot 4, pin 48, diseqc => e0 10 5c 89 4c
Jan 29 10:55:56 localhost minisatip[23809]: [29/01 10:55:56.261 signal]: get_signal_new took 1352 ms for adapter 0 handle 8 (status: -1, ber: 0, strength:0, snr: 0, force scan 0)
Jan 29 10:55:56 localhost minisatip[23809]: [29/01 10:55:56.361 signal]: BW 225KB/s, Total BW: 13 MB, ns/read 1319, r: 4, w: 5 fw: 0, tt: 5 ms
Jan 29 10:55:56 localhost minisatip[23809]: [29/01 10:55:56.665 signal]: get_signal_new adapter 0: status 3, strength -390 dBm -> 65279, snr 17000 dB -> 11140, BER: 0, err 0
Jan 29 10:55:56 localhost minisatip[23809]: [29/01 10:55:56.665 signal]: get_signal_new took 3 ms for adapter 0 handle 8 (status: 3, ber: 0, strength:254, snr: 43, force scan 0)

9000h commented 4 years ago

for the repeat a msleep seem to help

--- dvb.c.orig  2020-01-25 17:38:56.955153774 +0100
+++ dvb.c       2020-01-29 12:30:23.268717175 +0100
@@ -1573,6 +1573,7 @@
        if (ad->status == 0 && ((ad->tp.diseqc_param.switch_type == SWITCH_JESS) || (ad->tp.diseqc_param.switch_type == SWITCH_UNICABLE)))
        {
                adapter_lock(ad->id);
+               msleep(50);
                setup_switch(ad);
                adapter_unlock(ad->id);
        }

9000h commented 4 years ago

your fix (when corrected) and the additional wait before the repeated setup_switch seem to fix both situations now PR created

9000h commented 4 years ago

I'm still have another issue here with VDR which I could not catch/prove yet as it's intermitted happen.

the only unusual log have is this one: Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.912 signal]: get_signal_new took 213 ms for adapter 0 handle -1 (status: 31, ber: 0, strength:254, snr: 40, force scan 0)

hmm ad->fe -1 should also not happen as there is a check before maybe it's set from another thread or there is also a lock missing

the only place where this can come from is: https://github.com/catalinii/minisatip/blob/4682fb515c1b9b3bbff74f52d7c46a9069cc5989/src/adapter.c#L455

Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.658 main]: AD 4 [demux 4 0], setting filter on PID 4112 for fd 35
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.658 main]: reply -> 7 (192.168.178.114:56446) CL:0 [sock_id 7]:
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.658 main]: RTSP/1.0 200 OK
Jan 29 21:24:56 localhost minisatip[26115]: Date: Wed, Jan 29 20:24:56 2020 GMT
Jan 29 21:24:56 localhost minisatip[26115]: Session: 1315634022
Jan 29 21:24:56 localhost minisatip[26115]: CSeq: 40
Jan 29 21:24:56 localhost minisatip[26115]: Server: minisatip/1.0.2-4682fb5
Jan 29 21:24:56 localhost minisatip[26115]: RTP-Info: url=rtsp://192.168.178.129/stream=1;seq=42701;rtptime=968182
Jan 29 21:24:56 localhost minisatip[26115]: Range: npt=0.000-
Jan 29 21:24:56 localhost minisatip[26115]: #015
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.662 AD4]: Start streaming for stream 0, len 64696 to handle 8 => 192.168.178.114:37794
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: Requested adapter 0 close due to timeout 30 sec, result 1 max_rtime 4036972
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: closing DVR socket 11 pos 11 aid 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: closing adapter 0  -> fe:10 dvr:11, sock:11, fe_sock:-1
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: adapter.c:1080: get_adapter returns NULL for adapter_id 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: adapter.c:850: get_adapter returns NULL for adapter_id 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: Destroying mutex 0x55711dd90a68
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: done closing adapter 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.746 AD0]: sockets_del: sock 11 -> handle 11, sid -1, overflow bytes 0, allocated 0, used 0, unsend packets 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.747 AD0]: sockets_del: sock 11 Last open socket is at index 14 current_handle 11
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.747 AD0]: Destroying mutex 0x55711ddf31e8
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.847 AD0]: No enabled sockets for Thread ID 7f532dffb700 name AD0 ... exiting
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.847 AD0]: add_join_thread: pthread 7f532dffb700
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.850 AD4]: describe_adapter: sid 0, aid 4 => ver=1.1;tuner=5,90,1,4,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=0,16,17,20,570,4129,18,4145,4146,4147,4130,4131,4132,4133,4128,4112,4160,4161,4162,170
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.911 signal]: get_signal_new adapter 0: status 31, strength -390 dBm -> 65279, snr 15800 dB -> 10354, BER: 0, err 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.912 signal]: get_signal_new took 213 ms for adapter 0 handle -1 (status: 31, ber: 0, strength:254, snr: 40, force scan 0)
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.918 signal]: get_signal_new adapter 4: status 31, strength -64750 dBm -> 23101, snr 29500 dB -> 19332, BER: 0, err 0
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.918 signal]: get_signal_new took 7 ms for adapter 4 handle 14 (status: 31, ber: 0, strength:90, snr: 75, force scan 0)
Jan 29 21:24:56 localhost minisatip[26115]: [29/01 21:24:56.918 signal]: BW 1599KB/s, Total BW: 304 MB, ns/read 1052, r: 28, w: 38 fw: 0, tt: 29 ms
Jan 29 21:24:57 localhost minisatip[26115]: [29/01 21:24:57.025 signal]: get_signal_new adapter 4: status 31, strength -64750 dBm -> 23101, snr 29700 dB -> 19463, BER: 0, err 0
Jan 29 21:24:57 localhost minisatip[26115]: [29/01 21:24:57.026 signal]: get_signal_new took 7 ms for adapter 4 handle 14 (status: 31, ber: 0, strength:90, snr: 76, force scan 0)
Jan 29 21:24:57 localhost minisatip[26115]: [29/01 21:24:57.084 AD4]: describe_adapter: sid 0, aid 4 => ver=1.1;tuner=5,90,1,4,554.00,8,dvbt2,16k,qpsk,19128,,0,0,0;pids=0,16,17,20,570,4129,18,4145,4146,4147,4130,4131,4132,4133,4128,4112,4160,4161,4162,170
Jan 29 21:24:57 localhost minisatip[26115]: [29/01 21:24:57.102 main]: read RTSP (from handle 7 sock 7, len: 154, sid 0):
Jan 29 21:24:57 localhost minisatip[26115]: [29/01 21:24:57.102 main]: PLAY rtsp://192.168.178.129/stream=1?delpids=170,4112,4128 RTSP/1.0
Jan 29 21:24:57 localhost minisatip[26115]: CSeq: 41
Jan 29 21:24:57 localhost minisatip[26115]: Session: 1315634022
Jan 29 21:24:57 localhost minisatip[26115]: User-Agent: vdr-satip/2.4.1-GIT-826dea4 (device 0)

9000h commented 4 years ago

and why did the send_unicable not stay in the same thread

Jan 30 00:00:39 localhost minisatip[22049]: [30/01 00:00:39.036 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:00:39 localhost minisatip[22049]: [30/01 00:00:39.381 main]: send_unicable fd 7, freq 1612, ufreq 984, pos = 0, pol = 1, hiband = 0, slot 4, pin 48, diseqc => e0 10 5c 89 2b
Jan 30 00:00:42 localhost minisatip[22049]: [30/01 00:00:42.265 main]: send_unicable fd 19, freq 1743, ufreq 1020, pos = 0, pol = 1, hiband = 0, slot 5, pin 23, diseqc => e0 10 5c a9 55
Jan 30 00:00:46 localhost minisatip[22049]: [30/01 00:00:46.225 main]: send_unicable fd 7, freq 1612, ufreq 984, pos = 0, pol = 1, hiband = 0, slot 4, pin 48, diseqc => e0 10 5c 89 2b
Jan 30 00:00:52 localhost minisatip[22049]: [30/01 00:00:52.484 main]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:00:53 localhost minisatip[22049]: [30/01 00:00:53.835 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:00:55 localhost minisatip[22049]: [30/01 00:00:55.484 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:00:55 localhost minisatip[22049]: [30/01 00:00:55.833 main]: send_unicable fd 7, freq 1612, ufreq 984, pos = 0, pol = 1, hiband = 0, slot 4, pin 48, diseqc => e0 10 5c 89 2b
Jan 30 00:00:58 localhost minisatip[22049]: [30/01 00:00:58.889 main]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:00 localhost minisatip[22049]: [30/01 00:01:00.243 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:01 localhost minisatip[22049]: [30/01 00:01:01.848 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:03 localhost minisatip[22049]: [30/01 00:01:03.216 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:04 localhost minisatip[22049]: [30/01 00:01:04.400 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:06 localhost minisatip[22049]: [30/01 00:01:06.219 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c
Jan 30 00:01:07 localhost minisatip[22049]: [30/01 00:01:07.868 signal]: send_unicable fd 7, freq 1743, ufreq 984, pos = 0, pol = 1, hiband = 1, slot 4, pin 48, diseqc => e0 10 5c 8d 4c

catalinii / minisatip

no data sent for more than 1s #660