search

catalinii / minisatip

minisatip is an SATIP server for linux using local DVB-S2, DVB-C, DVB-T or ATSC cards
https://minisatip.org
332 stars 81 forks source link

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

Open lars18th opened 5 years ago

lars18th commented 5 years ago

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:

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

9000h commented 5 years ago

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

lars18th commented 5 years ago

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 commented 5 years ago

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

lars18th commented 5 years ago

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 commented 5 years ago

Hi @catalinii ,

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

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:

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

Thank you!

lars18th commented 5 years ago

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 commented 5 years ago

Hi @catalinii ,

No help?

catalinii commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

lars18th commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

lars18th commented 5 years ago

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 commented 1 year ago

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 commented 1 year ago

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