BUG in SATIPC: invalid SETUP command after the RTSP socket is closed

[lars18th]

Hi @catalinii ,

I'm trying to fix the minisatip server working with a XORO STB. The minisatip uses this STB as the SAT>IP server using the satip client functionality.

At time, it doesn't work (so I'm working on it). But I discovered a bug that's a side effect:

[03/10 16:02:32.582 AD1]: select_and_execute[11]: Close on socket 10 (id:11,sid:1) from 0.0.0.0:0 - type tcp errno 0
[03/10 16:02:32.582 AD1]: satip_close called for adapter 1, socket_id 11, handle 10 timeout 30000
[03/10 16:02:32.582 AD1]: closing adapter 1  -> fe:10 dvr:11, sock:13, fe_sock:11
[03/10 16:02:32.582 AD1]: satip device 192.168.1.37:554 is closing
[03/10 16:02:32.582 AD1]: satipc_http_request (ad 1): sending to sock 11:
TEARDOWN rtsp://192.168.1.37:554/stream=9 RTSP/1.0
CSeq: 10
Session: 957e8e2c


[03/10 16:02:32.583 AD1]: satip_close called for adapter 1, socket_id 11, handle 10 timeout 30000
[03/10 16:02:32.583 AD1]: sockets_del: sock 11 -> handle 10, sid 1, overflow bytes 0, allocated 0, used 0, unsend packets 0
[03/10 16:02:32.583 AD1]: sockets_del: 11 Last open socket is at index 13 current_handle 10
[03/10 16:02:32.583 AD1]: Destroying mutex 0x7f475f3482d8
[03/10 16:02:32.583 AD1]: satip_close called for adapter 1, socket_id 12, handle 12 timeout 0
[03/10 16:02:32.583 AD1]: sockets_del: sock 12 -> handle 12, sid 1, overflow bytes 0, allocated 0, used 0, unsend packets 0
[03/10 16:02:32.583 AD1]: sockets_del: 12 Last open socket is at index 13 current_handle 12
[03/10 16:02:32.583 AD1]: Destroying mutex 0x7f475f348438
[03/10 16:02:32.583 AD1]: adapter.c:1080: get_adapter returns NULL for adapter_id 1
[03/10 16:02:32.583 AD1]: adapter.c:850: get_adapter returns NULL for adapter_id 1
[03/10 16:02:32.583 AD1]: Destroying mutex 0x7f475f344d88
[03/10 16:02:32.583 AD1]: done closing adapter 1
[03/10 16:02:32.583 AD1]: sockets_del: sock 11 -> handle -1, sid -1, overflow bytes 0, allocated 0, used 0, unsend packets 0
[03/10 16:02:32.583 AD1]: sockets_del: 11 Last open socket is at index 13 current_handle -1
[03/10 16:02:32.583 AD1]: destroy disabled mutex 0x7f475f3482d8
[03/10 16:02:32.583 AD1]: Delete socket 11 done: sid -1
[03/10 16:02:32.583 AD1]: adapter.c:1332: get_adapter returns NULL for adapter_id 1
[03/10 16:02:32.583 AD1]: adapter.c:214: get_adapter returns NULL for adapter_id -1
[03/10 16:02:32.583 AD1]: closing DVR socket 11 pos 13 aid -1
[03/10 16:02:32.583 AD1]: sockets_del: sock 13 -> handle 11, sid -1, overflow bytes 0, allocated 0, used 0, unsend packets 0
[03/10 16:02:32.583 AD1]: sockets_del: 13 Last open socket is at index 13 current_handle 11
[03/10 16:02:32.583 AD1]: Destroying mutex 0x7f475f348598
[03/10 16:02:32.783 AD1]: adapter.c:1332: get_adapter returns NULL for adapter_id 1
Message repeated 1 times
[03/10 16:02:33.102 signal]: BW 488KB/s, Total BW: 2 MB, ns/read 288, r: 47, w: 381 fw: 0, tt: 13 ms
[03/10 16:02:33.383 AD1]: adapter.c:1332: get_adapter returns NULL for adapter_id 1
[03/10 16:02:33.684 AD1]: no data sent for more than 1s sid: 0 for 192.168.1.31:53042
[03/10 16:02:33.684 AD1]: adapter.c:1332: get_adapter returns NULL for adapter_id 1
Message repeated 3 times
[03/10 16:02:34.717 main]: read RTSP (from handle 7 sock 7, len: 108, sid 0):
[03/10 16:02:34.717 main]: detect_dvb_parameters (S)-> delpids=110,120,0,100,130
[03/10 16:02:34.717 main]: detect_dvb_parameters (E) -> src=-1, fe=-1, freq=-1, fec=-1, sr=-1, pol=-1, ro=-1, msys=-1, mtype=-1, plts=-1, bw=-1, inv=-1, pids=NULL - apids=NULL - dpids=110,120,0,100,130 x_pmt=NULL
[03/10 16:02:34.717 main]: Setup stream 0 parameters, sock_id 7, handle 7
[03/10 16:02:34.717 main]: copy_dvb_param start -> src=1, fe=0, freq=11954000, fec=3, sr=27500000, pol=2, ro=0, msys=5, mtype=0, plts=1, bw=8000000, inv=2, pids=NULL, apids=NULL, dpids=NULL x_pmt=NULL
[03/10 16:02:34.717 main]: copy_dvb_parameters -> src=1, fe=0, freq=11954000, fec=3 sr=27500000, pol=2, ro=0, msys=5, mtype=0, plts=1, bw=8000000, inv=2, pids=NULL, apids=NULL, dpids=110,120,0,100,130 x_pmt=NULL
[03/10 16:02:34.717 main]: Play for stream 0, type 2, rsock 8, adapter 1, sock_id 7, rsock_id 9, handle 7
[03/10 16:02:34.717 main]: stream.c:267: get_adapter returns NULL for adapter_id 1
[03/10 16:02:34.717 main]: adapter.c:1183: get_adapter returns NULL for adapter_id 1
[03/10 16:02:34.717 main]: adapter.c:2222: get_adapter returns NULL for adapter_id 1
[03/10 16:02:34.717 main]: stream.c:276: get_adapter returns NULL for adapter_id 1
[03/10 16:02:34.717 main]: get free adapter 0 - a[0] => e:0 m:0 sid_cnt:0 f:0 pol=0 sys: undefined undefined
[03/10 16:02:34.717 main]: Mutex init 0x7f475f344d88
[03/10 16:02:34.718 main]: New TCP socket 10 connected to 192.168.1.37:554
[03/10 16:02:34.718 main]: satipc: connected to SAT>IP server 192.168.1.37 port 554  handle 10
[03/10 16:02:34.718 main]: New UDP socket 11 bound to 0.0.0.0:6502
[03/10 16:02:34.718 main]: New UDP socket 12 bound to 0.0.0.0:6503
[03/10 16:02:34.718 main]: Mutex init 0x7f475f3482d8
[03/10 16:02:34.718 main]: sockets_add: handle socket 10 (type 1) returning socket sock 11 [0.0.0.0:0] read: 0x7f475ef141ba
[03/10 16:02:34.718 main]: Mutex init 0x7f475f348438
[03/10 16:02:34.718 main]: sockets_add: handle socket 12 (type 1) returning socket sock 12 [0.0.0.0:0] read: 0x7f475ef141ba
[03/10 16:02:34.718 main]: receive socket buffer size is 11550720 bytes
[03/10 16:02:34.718 main]: deleting pids on adapter 1, sid -1, pids=NULL
[03/10 16:02:34.718 main]: Dumping pids table for adapter 1, pid errors 1356
[03/10 16:02:34.718 main]: pid 110, fd 101, packets 10969, d/c errs 0/3, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 18, fd 101, packets 2619, d/c errs 0/3, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 130, fd 101, packets 542, d/c errs 0/3, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 120, fd 101, packets 476, d/c errs 0/3, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 0, fd 101, packets 128, d/c errs 0/6, flags 3, pmt -1, filter 0, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 100, fd 101, packets 33, d/c errs 0/4, flags 3, pmt 0, filter 2, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: Dumping pids table for adapter 1, pid errors 1356
[03/10 16:02:34.719 main]: pid 110, fd 101, packets 10969, d/c errs 0/3, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 18, fd 101, packets 2619, d/c errs 0/3, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 130, fd 101, packets 542, d/c errs 0/3, flags 3, pmt -1, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 120, fd 101, packets 476, d/c errs 0/3, flags 3, pmt 0, filter -1, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 0, fd 101, packets 128, d/c errs 0/6, flags 3, pmt -1, filter 0, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: pid 100, fd 101, packets 33, d/c errs 0/4, flags 3, pmt 0, filter 2, sock -1, sids: -1 -1 -1 -1 -1 -1 -1 -1
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 100, err 0
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 0, err 0
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 120, err 0
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 130, err 0
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 18, err 0
[03/10 16:02:34.719 main]: satipc: del_pid for aid 1, pid 110, err 0
[03/10 16:02:34.719 main]: satipc: commit for adapter 1 pids to add 0, pids to delete 6, expect_reply 0, force_commit 0 want_tune 0 do_tune 0, force_pids 0, sent_transport 0
[03/10 16:02:34.719 main]: satipc_http_request (ad 1): sending to sock 11:
SETUP rtsp://192.168.1.37:554/?&mtype=&pol=none&sr=0&plsc=0&pids=none RTSP/1.0
CSeq: 1
Transport: RTP/AVP;unicast;client_port=6502-6503


[03/10 16:02:34.719 main]: Mutex init 0x7f475f348598
[03/10 16:02:34.719 main]: sockets_add: handle socket 11 (type 5) returning socket sock 13 [0.0.0.0:0] read: 0x7f475ef141ba
[03/10 16:02:34.719 main]: set_socket_thread: thread 7f475d304700 for sockets 13
[03/10 16:02:34.719 main]: set_socket_thread: thread 7f475d304700 for sockets 12
[03/10 16:02:34.719 main]: set_socket_thread: thread 7f475d304700 for sockets 11
[03/10 16:02:34.719 main]: satipc_http_request (ad 1): queueing to sock 11:
OPTIONS rtsp://192.168.1.37:554/ RTSP/1.0
CSeq: 2
User-Agent: minisatip 1.0-unknown


[03/10 16:02:34.719 AD1]: Starting select_and_execute on thread ID 7f475d304700, thread_name AD1

The problem is this:

• Because some problem (I'm working on fix it, please be patient), the RTSP socket from the minisatip to the STB is closed.
• Then the satipc module sends a TEARDOWN (even if it isn't sended over the socket as it's closed), and it closes the adapter.
• But after the minisatip receives from his client the DELPIDS command, and it triggers a SETUP with invalid parameters (?&mtype=&pol=none&sr=0&plsc=0&pids=none).

So I suggest to fix this bug adding some workaround. Regards.

[9000h]

btw your minisatip ist probably not compiled right "minisatip 1.0-unknown" , it should look like "minisatip 1.0.2-679b7ca"

[lars18th]

btw your minisatip ist probably not compiled right "minisatip 1.0-unknown" , it should look like "minisatip 1.0.2-679b7ca"

It's compiled right, but the source is not from a git clone but from a ZIP. For this reason is ' minisatip 1.0-unknown' .

[9000h]

ok but this way it make it hard to guess which version is in use

[lars18th]

ok but this way it make it hard to guess which version is in use

For sure it's the last version!

This bug is real: When the RTSP socket to the SAT>IP server is closed (when running in satipc mode) then the Adapter is not properly closed.

Futhermore, it's quite easy to reproduce: configure a new minisatip instance in the middle, and configure it to work as client of another minisatip. The connect one client to the middle minisatip, and when running it then close (with an external tool) the RTSP socket in between the middle and the real server. Then check the LOGs.

I hope @catalinii will fix this problem, or will think in add some checks to not trigger a SETUP/PLAY command if the parameters are empty (see the ?&mtype=&pol=none&sr=0&plsc=0&pids=none). I feel this "assert" will be useful.

Regards.

[lars18th]

Hi @catalinii ,

I hope you can help me: The problem with the XORO server is reduced to this behaviour:

• When the SAT>IP client (the one connected to minisatip) requests a new channel, then minisatip using the satipc module does the SETUP and then the PLAY with the different addpids/delpids. All goes right (using my patch #612, without it the PLAY doesn't start), but after 1 second (just this time) the image stops in the client. In the LOG the RTSP socket between the minisatip server and the XORO SAT>IP server is closed, and then minisatip triggers the TEARDOWN (even the socket is closed). Here the precise point where the problem appears:

[04/10 12:08:05.798 AD1]: event on socket index 11 handle 10 type 1 spos 0 wpos 0 (poll fd: 10, events: 3, revents: 1)
[04/10 12:08:05.798 AD1]: Read NOK 0 (rlen:0/total:2000) bytes from 10 [s: 11 m: 11] -> 0x7f8f2b899300 (buf: 0x7f8f2b899300) - iteration 9 action 0x43356a
[04/10 12:08:05.798 AD1]: select_and_execute[11]: Close on socket 10 (sid:1) from 0.0.0.0:0 - type tcp errno 0
[04/10 12:08:05.799 AD1]: satip_close called for adapter 1, socket_id 11, handle 10 timeout 30000
[04/10 12:08:05.799 AD1]: closing adapter 1  -> fe:10 dvr:11, sock:13, fe_sock:11
[04/10 12:08:05.799 AD1]: satip device 192.168.1.34:554 is closing
[04/10 12:08:05.799 AD1]: satipc_http_request (ad 1): sending to sock 11:
TEARDOWN rtsp://192.168.1.34:554/stream=71 RTSP/1.0

Please, don't ask me for a full LOG. I'm trying to fix the problem for my self. And I'm sure of this:

• The SAT>IP server doesn't close the RSTP socket, it's inside the minisatip process that the socket is closed.
• The problem appears every time I do it with any frequency/channel.
• Inside the code, the problem is because the select in the RTSP socket of the satipc module (function select_and_execute()) detects some event in the socket but the read returns 0 bytes.

So the question is this: You know any reason for an event in this RTSP client socket without reading data?

Thank you!

[lars18th]

Hi @catalinii ,

You know any reason for an event in this RTSP client socket without reading data?

Please, any idea? I need your help to fix this problem!

[lars18th]

Hi @catalinii ,

No help?

[catalinii]

Hey,

In your log the line:

[04/10 12:08:05.798 AD1]: Read NOK 0 (rlen:0/total:2000) bytes from 10 [s: 11 m: 11] -> 0x7f8f2b899300 (buf: 0x7f8f2b899300) - iteration 9 action 0x43356a [04/10 12:08:05.798 AD1]: select_and_execute[11]: Close on socket 10 (sid:1) from 0.0.0.0:0 - type tcp errno 0 Indicates the server closed the connection. Mijisatip tends to write the TEARDOWN after that but if the socket ia already closed it will not succeed (ofc).

The behavior with middle and real.minisatip is by design. The reason is that if the real minisatip goes down (restart, crash, or the connection drops) the middle minisatip will retune once the real minisatip is back up.

[lars18th]

Hi @catalinii ,

Thank you for the response.

[04/10 12:08:05.798 AD1]: Read NOK 0 (rlen:0/total:2000) bytes from 10 [s: 11 m: 11] -> 0x7f8f2b899300 (buf: 0x7f8f2b899300) - iteration 9 action 0x43356a [04/10 12:08:05.798 AD1]: select_and_execute[11]: Close on socket 10 (sid:1) from 0.0.0.0:0 - type tcp errno 0 . Indicates the server closed the connection. ...

As I commented before the server has not closed the connection. I've completely checked it. And for this reason I ask you: How it's possible that the socket will be closed if the other part (the server) isn't closing it?

[catalinii]

The only way you can check is by doing tcdump on the box with minisatip. Again to me it seems like it did (read 0 means sockets is closed by the other side).

[lars18th]

The only way you can check is by doing tcdump on the box with minisatip. Again to me it seems like it did (read 0 means sockets is closed by the other side).

I do it already. And I can confirm that the other side doesn't close the socket. And for this reason I ask you: some part of the code is forcing to read from the socket when the socket has no new data. It's possible that some thread generate a fake socket activity?

[catalinii]

Can u upload the tcpdump maybe there is something else going on before the socket close?

If there is no data the read will return -1 not 0

[lars18th]

Hi @catalinii ,

The problem of SETUP rtsp://192.168.1.37:554/?&mtype=&pol=none&sr=0&plsc=0&pids=none RTSP/1.0 is resolved with this PR #638.

Please, commit it!

The pending trouble to fix is the TEARDOWN not sended when the adapter is closed: https://github.com/catalinii/minisatip/issues/636#issuecomment-552991373

Regards.

[lars18th]

The only way you can check is by doing tcdump on the box with minisatip. Again to me it seems like it did (read 0 means sockets is closed by the other side).

I do it already. And I can confirm that the other side doesn't close the socket. And for this reason I ask you: some part of the code is forcing to read from the socket when the socket has no new data. It's possible that some thread generate a fake socket activity?

Hi @catalinii ,

Regarding the problem of the phantom socket close (different to the trouble pointed before and resolved by my PR #638), I feel that not only the RTSP socket from the satipc module has this problem. I feel (I need to do more tests to confirm it) that all TCP sockets are randomly closed time to time. I've the intuition that after some time something like a timer is closing automatically every tcp socket. Even if the socket has activity.

So, please comment about this: You have implemented some type of TIMEOUTS associated to TCP sockets?

Perhaps this is the cause of the problem. Regards.

[9000h]

maybe there is also some relation to https://github.com/catalinii/minisatip/issues/502

[lars18th]

Hi @catalinii ,

The problem of SETUP rtsp://192.168.1.37:554/?&mtype=&pol=none&sr=0&plsc=0&pids=none RTSP/1.0 is resolved with this PR #638.

Please, commit it!

Now, really fixed after lasted commit. Please, review it and merge it. Regards.

[lars18th]

maybe there is also some relation to #502

Hi @9000h , I don't know, but in my case my last PRs #638 and #639 fix a lot of troubles with some SAT>IP servers. Please, try them with your Panasonic TV as server, as my new TV only has client functionality.

[9000h]

Hi, @lars18th , my Panasonic TV's are client only it's a lot of effort here an take some time to such tests with the Panasonic TV's as server. The TVIP (SAT->IP) from the Viera's are certified but maybe also not free of issues like the one I found here https://github.com/rofafor/vdr-plugin-satip/issues/56#issuecomment-451677572

[lars18th]

Hi @9000h ,

Yes it's true that the Panasonic ins't the best SAT>IP implementation. However, it's quite interesting to test it (as Client and as Server too).

In any case, please, check my last patches if you use the satipc module. Regards.

[9000h]

Hi @lars18th , for testing I did use my AMV 6490 as server (not certified by Astra). CU

[lars18th]

Hi @lars18th , for testing I did use my AMV 6490 as server (not certified by Astra).

This Fritzbox is for DVB-C, and I don't receive any DVB-C signal. In my case I use: one DD Octopus and different STBs with SAT>IP support (Mirage ALi, Xoro, OpenATV, etc.). For sure, we need to test with a lot of devices. :wink:

[lars18th]

This bug is related to this PR #817 that solves the trouble. However, a reimplementation it's requested. So the bug is pending to solve it.

[oneingan]

Hi @lars18th sorry if I kidnap this topic for talk about XORO SAT>IP Server. Do you have any problem when using 2 channels from same transponder. As related here https://www.kodinerds.net/index.php/Thread/56726-Megasat-SAT-IP-Server-3-Tvheadend-4-1-2437/

Maybe minisatip cient could workaround it?

Assumin XORO and Megasat MAG-8000 are same hardware.

EDIT: Wow I just discovery by casuality that this setup works well:

MEGASAT SAT>IP Server 3 --(LAN1)--> minisatip #1 client --(WAN)--> minisatip #2 client --(LAN2)--> TVH

while this 2 other setups fails (video glitches) when a new channel in same transponder starts using same tuner:

MEGASAT SAT>IP Server 3 --(LAN1)--> minisatip client --(LAN1)--> TVH

or

MEGASAT SAT>IP Server 3 --(LAN1)--> TVH